You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/09 21:02:16 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.7.0_21) - Build #
6059 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6059/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:53834/jq/ef 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:53834/jq/ef returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([FD053C3EE7F5A722:7CE3B22690AAC71E]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9380 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 144207 T351 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /jq/ef
[junit4:junit4] 2> 144213 T351 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1370803532023
[junit4:junit4] 2> 144214 T351 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 144214 T352 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 144314 T351 oasc.ZkTestServer.run start zk server on port:33858
[junit4:junit4] 2> 144315 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 144470 T358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f0070b7 name:ZooKeeperConnection Watcher:127.0.0.1:33858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 144470 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 144471 T351 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 144475 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 144477 T360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@61c729c1 name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 144477 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 144477 T351 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 144486 T351 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 144490 T351 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 144492 T351 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 144494 T351 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> 144495 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 144502 T351 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> 144503 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 144507 T351 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> 144507 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 144510 T351 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> 144511 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 144513 T351 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> 144513 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 144516 T351 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> 144517 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 144519 T351 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> 144520 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 144524 T351 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> 144525 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 144528 T351 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> 144528 T351 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 144618 T351 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 144621 T351 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46901
[junit4:junit4] 2> 144622 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 144622 T351 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 144623 T351 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343
[junit4:junit4] 2> 144623 T351 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/solr.xml
[junit4:junit4] 2> 144624 T351 oasc.CoreContainer.<init> New CoreContainer 1914639619
[junit4:junit4] 2> 144624 T351 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/'
[junit4:junit4] 2> 144625 T351 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/'
[junit4:junit4] 2> 144671 T351 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 144672 T351 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 144672 T351 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 144673 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 144673 T351 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 144674 T351 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 144674 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 144674 T351 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 144674 T351 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 144675 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 144678 T351 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 144679 T351 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33858/solr
[junit4:junit4] 2> 144679 T351 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 144680 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 144681 T371 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d47a4d4 name:ZooKeeperConnection Watcher:127.0.0.1:33858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 144682 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 144683 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 144687 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 144688 T373 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@342322ad name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 144689 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 144690 T351 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 144693 T351 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 144696 T351 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 144698 T351 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46901_jq%2Fef
[junit4:junit4] 2> 144699 T351 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46901_jq%2Fef
[junit4:junit4] 2> 144702 T351 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 144706 T351 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 144708 T351 oasc.Overseer.start Overseer (id=89836980274855939-127.0.0.1:46901_jq%2Fef-n_0000000000) starting
[junit4:junit4] 2> 144711 T351 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 144715 T375 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 144716 T351 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 144719 T351 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 144721 T351 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 144723 T374 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 144725 T376 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/collection1
[junit4:junit4] 2> 144725 T376 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 144726 T376 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 144726 T376 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 144727 T376 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/collection1/'
[junit4:junit4] 2> 144728 T376 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/collection1/lib/README' to classloader
[junit4:junit4] 2> 144728 T376 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 144761 T376 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 144788 T376 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 144790 T376 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 144794 T376 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 145096 T376 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 145097 T376 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 145099 T376 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 145102 T376 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 145127 T376 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 145128 T376 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370803532343/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/control/data/
[junit4:junit4] 2> 145128 T376 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2372f2d5
[junit4:junit4] 2> 145128 T376 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 145129 T376 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/control/data
[junit4:junit4] 2> 145129 T376 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/control/data/index/
[junit4:junit4] 2> 145129 T376 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 145130 T376 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/control/data/index
[junit4:junit4] 2> 145131 T376 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ca8fb9a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5069a89),segFN=segments_1,generation=1}
[junit4:junit4] 2> 145132 T376 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 145134 T376 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 145134 T376 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 145134 T376 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 145135 T376 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 145135 T376 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 145135 T376 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 145136 T376 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 145136 T376 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 145136 T376 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 145139 T376 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 145141 T376 oass.SolrIndexSearcher.<init> Opening Searcher@7887e423 main
[junit4:junit4] 2> 145141 T376 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/control/data/tlog
[junit4:junit4] 2> 145142 T376 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 145142 T376 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 145146 T377 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7887e423 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 145147 T376 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 145147 T376 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 146228 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 146229 T374 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:46901_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46901/jq/ef"}
[junit4:junit4] 2> 146230 T374 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 146230 T374 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 146236 T373 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> 147150 T376 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 147151 T376 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46901/jq/ef collection:control_collection shard:shard1
[junit4:junit4] 2> 147152 T376 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 147165 T376 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 147172 T376 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 147173 T376 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 147173 T376 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46901/jq/ef/collection1/
[junit4:junit4] 2> 147173 T376 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 147173 T376 oasc.SyncStrategy.syncToMe http://127.0.0.1:46901/jq/ef/collection1/ has no replicas
[junit4:junit4] 2> 147173 T376 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46901/jq/ef/collection1/
[junit4:junit4] 2> 147174 T376 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 147744 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 147756 T373 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> 147782 T376 oasc.ZkController.register We are http://127.0.0.1:46901/jq/ef/collection1/ and leader is http://127.0.0.1:46901/jq/ef/collection1/
[junit4:junit4] 2> 147782 T376 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46901/jq/ef
[junit4:junit4] 2> 147782 T376 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 147782 T376 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 147783 T376 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 147785 T376 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 147786 T351 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 147786 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 147787 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 147791 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 147793 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 147795 T380 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@771018bc name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 147795 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 147796 T351 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 147799 T351 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 147872 T351 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 147874 T351 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53834
[junit4:junit4] 2> 147875 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 147875 T351 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 147876 T351 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609
[junit4:junit4] 2> 147876 T351 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/solr.xml
[junit4:junit4] 2> 147876 T351 oasc.CoreContainer.<init> New CoreContainer 1945074821
[junit4:junit4] 2> 147877 T351 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/'
[junit4:junit4] 2> 147877 T351 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/'
[junit4:junit4] 2> 147921 T351 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 147922 T351 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 147922 T351 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 147922 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 147923 T351 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 147923 T351 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 147923 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 147923 T351 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 147924 T351 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 147924 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 147928 T351 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 147928 T351 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33858/solr
[junit4:junit4] 2> 147929 T351 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 147929 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 147931 T391 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37a0862f name:ZooKeeperConnection Watcher:127.0.0.1:33858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 147931 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 147932 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 147936 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 147938 T393 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22cf1138 name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 147938 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 147941 T351 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 148944 T351 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53834_jq%2Fef
[junit4:junit4] 2> 148947 T351 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53834_jq%2Fef
[junit4:junit4] 2> 148952 T380 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 148952 T373 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 148952 T393 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 148952 T373 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> 148956 T394 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/collection1
[junit4:junit4] 2> 148957 T394 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 148958 T394 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 148958 T394 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 148959 T394 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/collection1/'
[junit4:junit4] 2> 148959 T394 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/collection1/lib/README' to classloader
[junit4:junit4] 2> 148960 T394 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 148984 T394 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 149014 T394 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 149015 T394 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 149019 T394 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 149413 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 149414 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46901_jq%2Fef_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:46901_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46901/jq/ef"}
[junit4:junit4] 2> 149417 T373 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> 149417 T380 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> 149417 T393 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> 149452 T394 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 149454 T394 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 149456 T394 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 149459 T394 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 149483 T394 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 149483 T394 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370803535609/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty1/
[junit4:junit4] 2> 149484 T394 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2372f2d5
[junit4:junit4] 2> 149484 T394 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 149484 T394 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty1
[junit4:junit4] 2> 149484 T394 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty1/index/
[junit4:junit4] 2> 149485 T394 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 149485 T394 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty1/index
[junit4:junit4] 2> 149487 T394 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40be2e4a lockFactory=org.apache.lucene.store.NativeFSLockFactory@30207ec5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 149487 T394 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 149489 T394 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 149489 T394 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 149490 T394 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 149490 T394 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 149491 T394 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 149491 T394 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 149491 T394 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 149491 T394 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 149492 T394 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 149495 T394 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 149497 T394 oass.SolrIndexSearcher.<init> Opening Searcher@7afa253e main
[junit4:junit4] 2> 149497 T394 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty1/tlog
[junit4:junit4] 2> 149498 T394 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 149498 T394 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 149502 T395 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7afa253e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 149504 T394 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 149504 T394 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 150923 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 150924 T374 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:53834_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53834/jq/ef"}
[junit4:junit4] 2> 150925 T374 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 150925 T374 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 150932 T393 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> 150932 T373 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> 150932 T380 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> 151522 T394 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 151522 T394 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53834/jq/ef collection:collection1 shard:shard1
[junit4:junit4] 2> 151524 T394 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 151534 T394 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 151538 T394 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 151538 T394 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 151539 T394 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53834/jq/ef/collection1/
[junit4:junit4] 2> 151539 T394 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 151539 T394 oasc.SyncStrategy.syncToMe http://127.0.0.1:53834/jq/ef/collection1/ has no replicas
[junit4:junit4] 2> 151540 T394 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53834/jq/ef/collection1/
[junit4:junit4] 2> 151540 T394 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 152438 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 152446 T373 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> 152446 T393 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> 152446 T380 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> 152453 T394 oasc.ZkController.register We are http://127.0.0.1:53834/jq/ef/collection1/ and leader is http://127.0.0.1:53834/jq/ef/collection1/
[junit4:junit4] 2> 152453 T394 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53834/jq/ef
[junit4:junit4] 2> 152453 T394 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 152454 T394 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 152454 T394 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 152455 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 152456 T351 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 152457 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 152457 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 152529 T351 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 152532 T351 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47393
[junit4:junit4] 2> 152532 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 152533 T351 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 152533 T351 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271
[junit4:junit4] 2> 152534 T351 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/solr.xml
[junit4:junit4] 2> 152534 T351 oasc.CoreContainer.<init> New CoreContainer 1822765448
[junit4:junit4] 2> 152535 T351 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/'
[junit4:junit4] 2> 152535 T351 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/'
[junit4:junit4] 2> 152578 T351 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 152578 T351 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 152579 T351 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 152579 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 152579 T351 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 152579 T351 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 152580 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 152580 T351 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 152580 T351 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 152581 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 152584 T351 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 152585 T351 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33858/solr
[junit4:junit4] 2> 152585 T351 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 152586 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 152587 T407 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12f538ae name:ZooKeeperConnection Watcher:127.0.0.1:33858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 152587 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 152589 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 152593 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 152595 T409 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@511a4df8 name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 152595 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 152598 T351 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 153601 T351 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47393_jq%2Fef
[junit4:junit4] 2> 153603 T351 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47393_jq%2Fef
[junit4:junit4] 2> 153607 T393 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> 153608 T373 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 153608 T373 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> 153609 T380 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 153609 T409 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 153609 T380 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> 153611 T393 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 153618 T410 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/collection1
[junit4:junit4] 2> 153618 T410 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 153619 T410 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 153620 T410 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 153623 T410 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/collection1/'
[junit4:junit4] 2> 153624 T410 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/collection1/lib/README' to classloader
[junit4:junit4] 2> 153625 T410 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 153661 T410 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 153688 T410 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 153690 T410 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 153694 T410 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 153951 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 153952 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53834_jq%2Fef_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:53834_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53834/jq/ef"}
[junit4:junit4] 2> 153955 T373 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> 153955 T393 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> 153955 T409 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> 153955 T380 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> 153974 T410 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 153976 T410 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 153977 T410 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 153980 T410 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 154007 T410 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 154007 T410 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370803540271/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty2/
[junit4:junit4] 2> 154007 T410 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2372f2d5
[junit4:junit4] 2> 154008 T410 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 154008 T410 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty2
[junit4:junit4] 2> 154008 T410 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty2/index/
[junit4:junit4] 2> 154008 T410 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 154009 T410 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty2/index
[junit4:junit4] 2> 154011 T410 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fba198a lockFactory=org.apache.lucene.store.NativeFSLockFactory@301139ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> 154011 T410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 154013 T410 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 154014 T410 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 154014 T410 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 154015 T410 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 154015 T410 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 154016 T410 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 154016 T410 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 154016 T410 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 154017 T410 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 154020 T410 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 154022 T410 oass.SolrIndexSearcher.<init> Opening Searcher@7d6e5880 main
[junit4:junit4] 2> 154023 T410 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty2/tlog
[junit4:junit4] 2> 154023 T410 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 154023 T410 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 154031 T411 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7d6e5880 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 154034 T410 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 154034 T410 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 155461 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 155463 T374 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:47393_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47393/jq/ef"}
[junit4:junit4] 2> 155464 T374 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 155464 T374 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 155471 T409 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> 155472 T393 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> 155471 T373 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> 155471 T380 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> 156035 T410 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 156036 T410 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47393/jq/ef collection:collection1 shard:shard2
[junit4:junit4] 2> 156037 T410 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 156046 T410 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 156050 T410 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 156051 T410 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 156051 T410 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47393/jq/ef/collection1/
[junit4:junit4] 2> 156051 T410 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 156052 T410 oasc.SyncStrategy.syncToMe http://127.0.0.1:47393/jq/ef/collection1/ has no replicas
[junit4:junit4] 2> 156052 T410 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47393/jq/ef/collection1/
[junit4:junit4] 2> 156053 T410 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 156975 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 156982 T373 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> 156982 T393 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> 156982 T380 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> 156982 T409 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> 157012 T410 oasc.ZkController.register We are http://127.0.0.1:47393/jq/ef/collection1/ and leader is http://127.0.0.1:47393/jq/ef/collection1/
[junit4:junit4] 2> 157012 T410 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47393/jq/ef
[junit4:junit4] 2> 157012 T410 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 157013 T410 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 157013 T410 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 157016 T410 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 157018 T351 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 157018 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 157019 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 157105 T351 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 157108 T351 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59205
[junit4:junit4] 2> 157108 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 157108 T351 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 157109 T351 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837
[junit4:junit4] 2> 157109 T351 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/solr.xml
[junit4:junit4] 2> 157109 T351 oasc.CoreContainer.<init> New CoreContainer 767591361
[junit4:junit4] 2> 157110 T351 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/'
[junit4:junit4] 2> 157110 T351 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/'
[junit4:junit4] 2> 157151 T351 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 157152 T351 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 157152 T351 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 157152 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 157152 T351 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 157153 T351 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 157153 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 157153 T351 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 157154 T351 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 157154 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 157157 T351 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 157158 T351 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33858/solr
[junit4:junit4] 2> 157158 T351 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 157159 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 157161 T423 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@27f61e0c name:ZooKeeperConnection Watcher:127.0.0.1:33858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 157163 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 157165 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 157169 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 157171 T425 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3917cba7 name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 157171 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 157175 T351 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 158178 T351 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59205_jq%2Fef
[junit4:junit4] 2> 158181 T351 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59205_jq%2Fef
[junit4:junit4] 2> 158185 T393 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> 158186 T373 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 158186 T409 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 158187 T380 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 158187 T425 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 158186 T373 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> 158187 T380 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> 158187 T409 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> 158188 T393 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 158194 T426 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/collection1
[junit4:junit4] 2> 158194 T426 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 158195 T426 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 158195 T426 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 158197 T426 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/collection1/'
[junit4:junit4] 2> 158198 T426 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/collection1/lib/README' to classloader
[junit4:junit4] 2> 158198 T426 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 158227 T426 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 158256 T426 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 158257 T426 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 158262 T426 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 158487 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 158487 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47393_jq%2Fef_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:47393_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47393/jq/ef"}
[junit4:junit4] 2> 158491 T373 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> 158491 T393 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> 158491 T425 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> 158491 T409 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> 158491 T380 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> 158551 T426 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 158553 T426 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 158555 T426 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 158558 T426 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 158579 T426 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 158580 T426 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370803544837/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/
[junit4:junit4] 2> 158580 T426 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2372f2d5
[junit4:junit4] 2> 158580 T426 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 158581 T426 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3
[junit4:junit4] 2> 158581 T426 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index/
[junit4:junit4] 2> 158581 T426 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 158582 T426 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index
[junit4:junit4] 2> 158583 T426 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2929b15e lockFactory=org.apache.lucene.store.NativeFSLockFactory@10ced6e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 158583 T426 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 158586 T426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 158586 T426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 158586 T426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 158587 T426 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 158587 T426 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 158587 T426 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 158588 T426 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 158588 T426 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 158588 T426 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 158591 T426 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 158593 T426 oass.SolrIndexSearcher.<init> Opening Searcher@8049137 main
[junit4:junit4] 2> 158593 T426 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/tlog
[junit4:junit4] 2> 158594 T426 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 158594 T426 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 158597 T427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8049137 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 158599 T426 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 158599 T426 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 159997 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 159999 T374 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:59205_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59205/jq/ef"}
[junit4:junit4] 2> 159999 T374 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 160000 T374 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 160005 T373 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> 160006 T409 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> 160006 T380 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> 160006 T393 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> 160006 T425 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> 160601 T426 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 160602 T426 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59205/jq/ef collection:collection1 shard:shard1
[junit4:junit4] 2> 160607 T426 oasc.ZkController.register We are http://127.0.0.1:59205/jq/ef/collection1/ and leader is http://127.0.0.1:53834/jq/ef/collection1/
[junit4:junit4] 2> 160607 T426 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59205/jq/ef
[junit4:junit4] 2> 160607 T426 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 160608 T426 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C158 name=collection1 org.apache.solr.core.SolrCore@7c26c680 url=http://127.0.0.1:59205/jq/ef/collection1 node=127.0.0.1:59205_jq%2Fef C158_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59205_jq%2Fef, base_url=http://127.0.0.1:59205/jq/ef}
[junit4:junit4] 2> 160608 T428 C158 P59205 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 160609 T426 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 160610 T428 C158 P59205 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 160610 T428 C158 P59205 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 160610 T428 C158 P59205 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 160611 T351 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 160612 T428 C158 P59205 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 160612 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 160614 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 160623 T387 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:59205_jq%2Fef_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 160703 T351 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 160706 T351 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37028
[junit4:junit4] 2> 160706 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 160707 T351 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 160707 T351 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432
[junit4:junit4] 2> 160708 T351 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/solr.xml
[junit4:junit4] 2> 160708 T351 oasc.CoreContainer.<init> New CoreContainer 2084221876
[junit4:junit4] 2> 160709 T351 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/'
[junit4:junit4] 2> 160709 T351 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/'
[junit4:junit4] 2> 160766 T351 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 160767 T351 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 160767 T351 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 160767 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 160768 T351 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 160768 T351 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 160768 T351 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 160769 T351 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 160769 T351 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 160769 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 160773 T351 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 160774 T351 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:33858/solr
[junit4:junit4] 2> 160774 T351 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 160775 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 160776 T440 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17ec0f54 name:ZooKeeperConnection Watcher:127.0.0.1:33858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 160777 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 160779 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 160783 T351 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 160784 T442 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f93aeb6 name:ZooKeeperConnection Watcher:127.0.0.1:33858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 160784 T351 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 160788 T351 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 161511 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 161512 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59205_jq%2Fef_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:59205_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59205/jq/ef"}
[junit4:junit4] 2> 161519 T373 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> 161519 T442 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> 161520 T393 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> 161519 T409 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> 161519 T380 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> 161519 T425 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> 161624 T387 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:59205_jq%2Fef_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 161624 T387 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:59205_jq%252Fef_collection1&state=recovering&nodeName=127.0.0.1:59205_jq%252Fef&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 161791 T351 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37028_jq%2Fef
[junit4:junit4] 2> 161793 T351 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37028_jq%2Fef
[junit4:junit4] 2> 161796 T393 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> 161797 T425 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 161797 T380 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 161797 T425 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 161797 T409 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 161797 T373 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 161798 T409 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 161798 T442 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 161797 T380 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 161800 T442 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 161799 T393 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 161799 T373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 161810 T443 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/collection1
[junit4:junit4] 2> 161810 T443 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 161811 T443 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 161812 T443 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 161814 T443 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/collection1/'
[junit4:junit4] 2> 161815 T443 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/collection1/lib/README' to classloader
[junit4:junit4] 2> 161816 T443 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 161857 T443 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 161884 T443 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 161885 T443 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 161889 T443 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 162161 T443 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 162163 T443 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 162164 T443 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 162167 T443 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 162194 T443 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 162194 T443 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370803548432/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/
[junit4:junit4] 2> 162194 T443 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2372f2d5
[junit4:junit4] 2> 162195 T443 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 162196 T443 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4
[junit4:junit4] 2> 162196 T443 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index/
[junit4:junit4] 2> 162196 T443 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 162197 T443 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index
[junit4:junit4] 2> 162199 T443 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7adb13c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@30c50487),segFN=segments_1,generation=1}
[junit4:junit4] 2> 162199 T443 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 162201 T443 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 162201 T443 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 162201 T443 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 162202 T443 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 162202 T443 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 162202 T443 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 162203 T443 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 162203 T443 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 162203 T443 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 162206 T443 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 162208 T443 oass.SolrIndexSearcher.<init> Opening Searcher@387fb0a2 main
[junit4:junit4] 2> 162208 T443 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/tlog
[junit4:junit4] 2> 162209 T443 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 162209 T443 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 162213 T444 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@387fb0a2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 162215 T443 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 162215 T443 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 163028 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 163030 T374 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:37028_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37028/jq/ef"}
[junit4:junit4] 2> 163030 T374 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 163030 T374 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 163037 T373 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> 163037 T380 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> 163038 T409 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> 163037 T425 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> 163038 T393 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> 163038 T442 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> 163216 T443 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 163216 T443 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37028/jq/ef collection:collection1 shard:shard2
[junit4:junit4] 2> 163221 T443 oasc.ZkController.register We are http://127.0.0.1:37028/jq/ef/collection1/ and leader is http://127.0.0.1:47393/jq/ef/collection1/
[junit4:junit4] 2> 163222 T443 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37028/jq/ef
[junit4:junit4] 2> 163222 T443 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 163222 T443 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C159 name=collection1 org.apache.solr.core.SolrCore@7a3816b0 url=http://127.0.0.1:37028/jq/ef/collection1 node=127.0.0.1:37028_jq%2Fef C159_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:37028_jq%2Fef, base_url=http://127.0.0.1:37028/jq/ef}
[junit4:junit4] 2> 163223 T445 C159 P37028 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 163224 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 163224 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 163225 T445 C159 P37028 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 163225 T445 C159 P37028 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 163226 T351 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 163227 T351 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 163227 T445 C159 P37028 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 163228 T351 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 163237 T405 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:37028_jq%2Fef_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 163237 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 163239 T351 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 163240 T351 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 163241 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C160 name=collection1 org.apache.solr.core.SolrCore@7c26c680 url=http://127.0.0.1:59205/jq/ef/collection1 node=127.0.0.1:59205_jq%2Fef C160_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59205_jq%2Fef, base_url=http://127.0.0.1:59205/jq/ef}
[junit4:junit4] 2> 163625 T428 C160 P59205 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53834/jq/ef/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 163626 T428 C160 P59205 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59205/jq/ef START replicas=[http://127.0.0.1:53834/jq/ef/collection1/] nUpdates=100
[junit4:junit4] 2> 163626 T428 C160 P59205 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 163627 T428 C160 P59205 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 163627 T428 C160 P59205 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 163627 T428 C160 P59205 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 163627 T428 C160 P59205 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 163628 T428 C160 P59205 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53834/jq/ef/collection1/. core=collection1
[junit4:junit4] 2> 163628 T428 C160 P59205 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C161 name=collection1 org.apache.solr.core.SolrCore@32db51d url=http://127.0.0.1:53834/jq/ef/collection1 node=127.0.0.1:53834_jq%2Fef C161_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53834_jq%2Fef, base_url=http://127.0.0.1:53834/jq/ef, leader=true}
[junit4:junit4] 2> 163631 T388 C161 P53834 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 163636 T386 C161 P53834 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 163639 T386 C161 P53834 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40be2e4a lockFactory=org.apache.lucene.store.NativeFSLockFactory@30207ec5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 163640 T386 C161 P53834 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 163641 T386 C161 P53834 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40be2e4a lockFactory=org.apache.lucene.store.NativeFSLockFactory@30207ec5),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40be2e4a lockFactory=org.apache.lucene.store.NativeFSLockFactory@30207ec5),segFN=segments_2,generation=2}
[junit4:junit4] 2> 163641 T386 C161 P53834 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 163642 T386 C161 P53834 oass.SolrIndexSearcher.<init> Opening Searcher@6dc5abd5 realtime
[junit4:junit4] 2> 163643 T386 C161 P53834 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 163643 T386 C161 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 163645 T428 C160 P59205 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 163645 T428 C160 P59205 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 163649 T389 C161 P53834 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 163649 T389 C161 P53834 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 163650 T428 C160 P59205 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 163651 T428 C160 P59205 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 163651 T428 C160 P59205 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 163654 T388 C161 P53834 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 163655 T428 C160 P59205 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 163658 T428 C160 P59205 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index.20130609204551466
[junit4:junit4] 2> 163658 T428 C160 P59205 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3ecb8b16 lockFactory=org.apache.lucene.store.NativeFSLockFactory@582871c3) fullCopy=false
[junit4:junit4] 2> 163661 T386 C161 P53834 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 163663 T428 C160 P59205 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 163664 T428 C160 P59205 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 163664 T428 C160 P59205 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 163667 T428 C160 P59205 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2929b15e lockFactory=org.apache.lucene.store.NativeFSLockFactory@10ced6e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2929b15e lockFactory=org.apache.lucene.store.NativeFSLockFactory@10ced6e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 163668 T428 C160 P59205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 163668 T428 C160 P59205 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 163669 T428 C160 P59205 oass.SolrIndexSearcher.<init> Opening Searcher@43f8931b main
[junit4:junit4] 2> 163671 T427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@43f8931b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 163672 T428 C160 P59205 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index.20130609204551466 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index.20130609204551466;done=true>>]
[junit4:junit4] 2> 163673 T428 C160 P59205 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index.20130609204551466
[junit4:junit4] 2> 163673 T428 C160 P59205 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty3/index.20130609204551466
[junit4:junit4] 2> 163674 T428 C160 P59205 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 163674 T428 C160 P59205 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 163674 T428 C160 P59205 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 163675 T428 C160 P59205 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 163676 T428 C160 P59205 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 164244 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 164545 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 164547 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:37028_jq%2Fef_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:37028_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37028/jq/ef"}
[junit4:junit4] 2> 164565 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59205_jq%2Fef_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:59205_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59205/jq/ef"}
[junit4:junit4] 2> 164569 T373 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> 164570 T442 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> 164570 T425 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> 164569 T393 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> 164570 T380 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> 164570 T409 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> 165238 T405 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:37028_jq%2Fef_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 165238 T405 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:37028_jq%252Fef_collection1&state=recovering&nodeName=127.0.0.1:37028_jq%252Fef&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 2> 165246 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 166249 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C159_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:37028_jq%2Fef, base_url=http://127.0.0.1:37028/jq/ef}
[junit4:junit4] 2> 167240 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47393/jq/ef/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 167240 T445 C159 P37028 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:37028/jq/ef START replicas=[http://127.0.0.1:47393/jq/ef/collection1/] nUpdates=100
[junit4:junit4] 2> 167241 T445 C159 P37028 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 167241 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 167241 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 167241 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 167241 T445 C159 P37028 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 167242 T445 C159 P37028 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47393/jq/ef/collection1/. core=collection1
[junit4:junit4] 2> 167242 T445 C159 P37028 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C162 name=collection1 org.apache.solr.core.SolrCore@34f89555 url=http://127.0.0.1:47393/jq/ef/collection1 node=127.0.0.1:47393_jq%2Fef C162_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47393_jq%2Fef, base_url=http://127.0.0.1:47393/jq/ef, leader=true}
[junit4:junit4] 2> 167247 T405 C162 P47393 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 167249 T404 C162 P47393 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 167251 T404 C162 P47393 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fba198a lockFactory=org.apache.lucene.store.NativeFSLockFactory@301139ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> 167251 T404 C162 P47393 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 167251 T404 C162 P47393 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fba198a lockFactory=org.apache.lucene.store.NativeFSLockFactory@301139ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fba198a lockFactory=org.apache.lucene.store.NativeFSLockFactory@301139ad),segFN=segments_2,generation=2}
[junit4:junit4] 2> 167252 T404 C162 P47393 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 167252 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 167252 T404 C162 P47393 oass.SolrIndexSearcher.<init> Opening Searcher@f5b5413 realtime
[junit4:junit4] 2> 167253 T404 C162 P47393 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 167253 T404 C162 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef 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> 167254 T445 C159 P37028 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 167254 T445 C159 P37028 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 167256 T402 C162 P47393 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 167256 T402 C162 P47393 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 167256 T445 C159 P37028 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 167257 T445 C159 P37028 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 167257 T445 C159 P37028 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 167259 T405 C162 P47393 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 167260 T445 C159 P37028 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 167260 T445 C159 P37028 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index.20130609204555070
[junit4:junit4] 2> 167260 T445 C159 P37028 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b4f2b68 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47851c98) fullCopy=false
[junit4:junit4] 2> 167263 T404 C162 P47393 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 167264 T445 C159 P37028 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 167264 T445 C159 P37028 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 167265 T445 C159 P37028 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 167266 T445 C159 P37028 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7adb13c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@30c50487),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7adb13c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@30c50487),segFN=segments_2,generation=2}
[junit4:junit4] 2> 167266 T445 C159 P37028 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 167266 T445 C159 P37028 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 167267 T445 C159 P37028 oass.SolrIndexSearcher.<init> Opening Searcher@553bb40d main
[junit4:junit4] 2> 167267 T444 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@553bb40d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 167268 T445 C159 P37028 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index.20130609204555070 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index.20130609204555070;done=true>>]
[junit4:junit4] 2> 167268 T445 C159 P37028 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index.20130609204555070
[junit4:junit4] 2> 167268 T445 C159 P37028 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index.20130609204555070
[junit4:junit4] 2> 167268 T445 C159 P37028 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 167268 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 167269 T445 C159 P37028 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 167269 T445 C159 P37028 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 167270 T445 C159 P37028 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 167578 T374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 167580 T374 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:37028_jq%2Fef_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:37028_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37028/jq/ef"}
[junit4:junit4] 2> 167587 T373 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> 167587 T380 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> 167587 T393 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> 167587 T442 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> 167587 T425 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> 167588 T409 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> 168254 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 168255 T351 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C163 name=collection1 org.apache.solr.core.SolrCore@43d1f9d6 url=http://127.0.0.1:46901/jq/ef/collection1 node=127.0.0.1:46901_jq%2Fef C163_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:46901_jq%2Fef, base_url=http://127.0.0.1:46901/jq/ef, leader=true}
[junit4:junit4] 2> 168267 T369 C163 P46901 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 168271 T369 C163 P46901 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ca8fb9a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5069a89),segFN=segments_1,generation=1}
[junit4:junit4] 2> 168271 T369 C163 P46901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 168273 T369 C163 P46901 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ca8fb9a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5069a89),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ca8fb9a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5069a89),segFN=segments_2,generation=2}
[junit4:junit4] 2> 168273 T369 C163 P46901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 168274 T369 C163 P46901 oass.SolrIndexSearcher.<init> Opening Searcher@297059f6 main
[junit4:junit4] 2> 168275 T369 C163 P46901 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 168277 T377 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@297059f6 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 168278 T369 C163 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 168286 T388 C161 P53834 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 168288 T388 C161 P53834 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40be2e4a lockFactory=org.apache.lucene.store.NativeFSLockFactory@30207ec5),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40be2e4a lockFactory=org.apache.lucene.store.NativeFSLockFactory@30207ec5),segFN=segments_3,generation=3}
[junit4:junit4] 2> 168288 T388 C161 P53834 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 168289 T388 C161 P53834 oass.SolrIndexSearcher.<init> Opening Searcher@2c11ad70 main
[junit4:junit4] 2> 168290 T388 C161 P53834 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 168291 T395 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c11ad70 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 168292 T388 C161 P53834 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:59205/jq/ef/collection1/, StdNode: http://127.0.0.1:47393/jq/ef/collection1/, StdNode: http://127.0.0.1:37028/jq/ef/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 168297 T404 C162 P47393 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 168298 T404 C162 P47393 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fba198a lockFactory=org.apache.lucene.store.NativeFSLockFactory@301139ad),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fba198a lockFactory=org.apache.lucene.store.NativeFSLockFactory@301139ad),segFN=segments_3,generation=3}
[junit4:junit4] 2> 168298 T404 C162 P47393 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 168299 T404 C162 P47393 oass.SolrIndexSearcher.<init> Opening Searcher@645c3d98 main
[junit4:junit4] 2> 168300 T404 C162 P47393 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 168303 T411 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@645c3d98 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 168304 T404 C162 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> C160_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59205_jq%2Fef, base_url=http://127.0.0.1:59205/jq/ef}
[junit4:junit4] 2> 168305 T421 C160 P59205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C159_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:37028_jq%2Fef, base_url=http://127.0.0.1:37028/jq/ef}
[junit4:junit4] 2> 168306 T436 C159 P37028 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 168307 T421 C160 P59205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2929b15e lockFactory=org.apache.lucene.store.NativeFSLockFactory@10ced6e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2929b15e lockFactory=org.apache.lucene.store.NativeFSLockFactory@10ced6e6),segFN=segments_3,generation=3}
[junit4:junit4] 2> 168308 T421 C160 P59205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 168308 T436 C159 P37028 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7adb13c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@30c50487),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7adb13c1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@30c50487),segFN=segments_3,generation=3}
[junit4:junit4] 2> 168309 T436 C159 P37028 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 168309 T421 C160 P59205 oass.SolrIndexSearcher.<init> Opening Searcher@1466c555 main
[junit4:junit4] 2> 168310 T436 C159 P37028 oass.SolrIndexSearcher.<init> Opening Searcher@37637d96 main
[junit4:junit4] 2> 168311 T421 C160 P59205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 168311 T436 C159 P37028 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 168312 T427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1466c555 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 168312 T444 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@37637d96 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> ASYNC NEW_CORE C164 name=collection1 org.apache.solr.core.SolrCore@7c26c680 url=http://127.0.0.1:59205/jq/ef/collection1 node=127.0.0.1:59205_jq%2Fef C164_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59205_jq%2Fef, base_url=http://127.0.0.1:59205/jq/ef}
[junit4:junit4] 2> 168319 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> ASYNC NEW_CORE C165 name=collection1 org.apache.solr.core.SolrCore@7a3816b0 url=http://127.0.0.1:37028/jq/ef/collection1 node=127.0.0.1:37028_jq%2Fef C165_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:37028_jq%2Fef, base_url=http://127.0.0.1:37028/jq/ef}
[junit4:junit4] 2> 168320 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> ASYNC NEW_CORE C166 name=collection1 org.apache.solr.core.SolrCore@32db51d url=http://127.0.0.1:53834/jq/ef/collection1 node=127.0.0.1:53834_jq%2Fef C166_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53834_jq%2Fef, base_url=http://127.0.0.1:53834/jq/ef, leader=true}
[junit4:junit4] 2> 168321 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 35
[junit4:junit4] 2> 168323 T351 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 168328 T387 C166 P53834 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 168332 T420 C164 P59205 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C167 name=collection1 org.apache.solr.core.SolrCore@34f89555 url=http://127.0.0.1:47393/jq/ef/collection1 node=127.0.0.1:47393_jq%2Fef C167_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47393_jq%2Fef, base_url=http://127.0.0.1:47393/jq/ef, leader=true}
[junit4:junit4] 2> 168335 T402 C167 P47393 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 168338 T435 C165 P37028 oasc.SolrCore.execute [collection1] webapp=/jq/ef path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C168 name=collection1 org.apache.solr.core.SolrCore@43d1f9d6 url=http://127.0.0.1:46901/jq/ef/collection1 node=127.0.0.1:46901_jq%2Fef C168_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:46901_jq%2Fef, base_url=http://127.0.0.1:46901/jq/ef, leader=true}
[junit4:junit4] 2> 170344 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437391711793840128)} 0 2
[junit4:junit4] 2> 170354 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={update.distrib=FROMLEADER&_version_=-1437391711799083008&update.from=http://127.0.0.1:53834/jq/ef/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437391711799083008)} 0 2
[junit4:junit4] 2> 170358 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={update.distrib=FROMLEADER&_version_=-1437391711803277312&update.from=http://127.0.0.1:47393/jq/ef/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437391711803277312)} 0 1
[junit4:junit4] 2> 170359 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437391711803277312)} 0 7
[junit4:junit4] 2> 170360 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437391711799083008)} 0 12
[junit4:junit4] 2> 170366 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[0 (1437391711815860224)]} 0 2
[junit4:junit4] 2> 170374 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1437391711821103104)]} 0 1
[junit4:junit4] 2> 170375 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[0 (1437391711821103104)]} 0 6
[junit4:junit4] 2> 170380 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[1 (1437391711831588864)]} 0 1
[junit4:junit4] 2> 170388 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1437391711836831744)]} 0 1
[junit4:junit4] 2> 170389 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[1 (1437391711836831744)]} 0 5
[junit4:junit4] 2> 170393 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[2 (1437391711845220352)]} 0 1
[junit4:junit4] 2> 170400 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1437391711849414656)]} 0 1
[junit4:junit4] 2> 170402 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[2 (1437391711849414656)]} 0 6
[junit4:junit4] 2> 170405 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[3 (1437391711858851840)]} 0 0
[junit4:junit4] 2> 170416 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1437391711865143296)]} 0 1
[junit4:junit4] 2> 170417 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1437391711865143296)]} 0 6
[junit4:junit4] 2> 170418 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[3]} 0 10
[junit4:junit4] 2> 170422 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[4 (1437391711875629056)]} 0 1
[junit4:junit4] 2> 170429 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1437391711879823360)]} 0 1
[junit4:junit4] 2> 170431 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[4 (1437391711879823360)]} 0 6
[junit4:junit4] 2> 170433 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[5 (1437391711888211968)]} 0 0
[junit4:junit4] 2> 170439 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1437391711891357696)]} 0 1
[junit4:junit4] 2> 170439 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[5 (1437391711891357696)]} 0 3
[junit4:junit4] 2> 170442 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[6 (1437391711897649152)]} 0 0
[junit4:junit4] 2> 170447 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1437391711900794880)]} 0 0
[junit4:junit4] 2> 170448 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[6 (1437391711900794880)]} 0 3
[junit4:junit4] 2> 170451 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[7 (1437391711907086336)]} 0 0
[junit4:junit4] 2> 170456 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1437391711910232064)]} 0 0
[junit4:junit4] 2> 170457 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[7 (1437391711910232064)]} 0 4
[junit4:junit4] 2> 170459 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[8 (1437391711915474944)]} 0 0
[junit4:junit4] 2> 170466 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1437391711919669248)]} 0 1
[junit4:junit4] 2> 170466 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1437391711919669248)]} 0 3
[junit4:junit4] 2> 170467 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[8]} 0 5
[junit4:junit4] 2> 170470 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[9 (1437391711925960704)]} 0 1
[junit4:junit4] 2> 170477 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1437391711931203584)]} 0 1
[junit4:junit4] 2> 170477 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1437391711931203584)]} 0 3
[junit4:junit4] 2> 170478 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[9]} 0 6
[junit4:junit4] 2> 170481 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[10 (1437391711937495040)]} 0 1
[junit4:junit4] 2> 170488 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437391711942737920)]} 0 1
[junit4:junit4] 2> 170489 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1437391711942737920)]} 0 4
[junit4:junit4] 2> 170489 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[10]} 0 6
[junit4:junit4] 2> 170492 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[11 (1437391711950077952)]} 0 1
[junit4:junit4] 2> 170499 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437391711954272256)]} 0 1
[junit4:junit4] 2> 170499 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1437391711954272256)]} 0 3
[junit4:junit4] 2> 170500 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[11]} 0 6
[junit4:junit4] 2> 170503 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[12 (1437391711961612288)]} 0 1
[junit4:junit4] 2> 170508 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437391711964758016)]} 0 0
[junit4:junit4] 2> 170509 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[12 (1437391711964758016)]} 0 3
[junit4:junit4] 2> 170512 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[13 (1437391711971049472)]} 0 0
[junit4:junit4] 2> 170521 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437391711977340928)]} 0 1
[junit4:junit4] 2> 170522 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1437391711977340928)]} 0 5
[junit4:junit4] 2> 170522 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[13]} 0 7
[junit4:junit4] 2> 170526 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[14 (1437391711984680960)]} 0 0
[junit4:junit4] 2> 170531 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437391711987826688)]} 0 0
[junit4:junit4] 2> 170532 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[14 (1437391711987826688)]} 0 4
[junit4:junit4] 2> 170536 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[15 (1437391711995166720)]} 0 1
[junit4:junit4] 2> 170542 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437391711999361024)]} 0 1
[junit4:junit4] 2> 170543 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[15 (1437391711999361024)]} 0 4
[junit4:junit4] 2> 170547 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[16 (1437391712006701056)]} 0 1
[junit4:junit4] 2> 170557 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437391712014041088)]} 0 1
[junit4:junit4] 2> 170558 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1437391712014041088)]} 0 5
[junit4:junit4] 2> 170559 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[16]} 0 9
[junit4:junit4] 2> 170563 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[17 (1437391712023478272)]} 0 1
[junit4:junit4] 2> 170570 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437391712027672576)]} 0 1
[junit4:junit4] 2> 170571 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[17 (1437391712027672576)]} 0 5
[junit4:junit4] 2> 170575 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[18 (1437391712037109760)]} 0 1
[junit4:junit4] 2> 170586 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437391712044449792)]} 0 1
[junit4:junit4] 2> 170587 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1437391712044449792)]} 0 5
[junit4:junit4] 2> 170588 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[18]} 0 9
[junit4:junit4] 2> 170593 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[19 (1437391712054935552)]} 0 1
[junit4:junit4] 2> 170603 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437391712062275584)]} 0 1
[junit4:junit4] 2> 170604 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1437391712062275584)]} 0 5
[junit4:junit4] 2> 170605 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[19]} 0 9
[junit4:junit4] 2> 170610 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[20 (1437391712072761344)]} 0 1
[junit4:junit4] 2> 170620 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437391712080101376)]} 0 1
[junit4:junit4] 2> 170621 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1437391712080101376)]} 0 5
[junit4:junit4] 2> 170623 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[20]} 0 10
[junit4:junit4] 2> 170627 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[21 (1437391712091635712)]} 0 1
[junit4:junit4] 2> 170634 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437391712094781440)]} 0 1
[junit4:junit4] 2> 170635 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[21 (1437391712094781440)]} 0 5
[junit4:junit4] 2> 170639 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[22 (1437391712103170048)]} 0 1
[junit4:junit4] 2> 170649 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437391712110510080)]} 0 1
[junit4:junit4] 2> 170650 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1437391712110510080)]} 0 5
[junit4:junit4] 2> 170651 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[22]} 0 9
[junit4:junit4] 2> 170655 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[23 (1437391712120995840)]} 0 1
[junit4:junit4] 2> 170662 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437391712125190144)]} 0 1
[junit4:junit4] 2> 170663 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[23 (1437391712125190144)]} 0 5
[junit4:junit4] 2> 170667 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[24 (1437391712133578752)]} 0 1
[junit4:junit4] 2> 170678 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437391712140918784)]} 0 1
[junit4:junit4] 2> 170679 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1437391712140918784)]} 0 6
[junit4:junit4] 2> 170680 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[24]} 0 9
[junit4:junit4] 2> 170684 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[25 (1437391712151404544)]} 0 1
[junit4:junit4] 2> 170693 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437391712157696000)]} 0 0
[junit4:junit4] 2> 170694 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[25 (1437391712157696000)]} 0 4
[junit4:junit4] 2> 170694 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[25]} 0 7
[junit4:junit4] 2> 170698 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[26 (1437391712166084608)]} 0 1
[junit4:junit4] 2> 170706 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437391712171327488)]} 0 0
[junit4:junit4] 2> 170707 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1437391712171327488)]} 0 4
[junit4:junit4] 2> 170707 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[26]} 0 6
[junit4:junit4] 2> 170710 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[27 (1437391712178667520)]} 0 1
[junit4:junit4] 2> 170715 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437391712180764672)]} 0 0
[junit4:junit4] 2> 170716 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[27 (1437391712180764672)]} 0 4
[junit4:junit4] 2> 170719 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[28 (1437391712187056128)]} 0 1
[junit4:junit4] 2> 170726 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437391712192299008)]} 0 1
[junit4:junit4] 2> 170727 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1437391712192299008)]} 0 4
[junit4:junit4] 2> 170727 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[28]} 0 6
[junit4:junit4] 2> 170730 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[29 (1437391712199639040)]} 0 1
[junit4:junit4] 2> 170735 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437391712202784768)]} 0 0
[junit4:junit4] 2> 170736 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[29 (1437391712202784768)]} 0 4
[junit4:junit4] 2> 170739 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[30 (1437391712209076224)]} 0 1
[junit4:junit4] 2> 170746 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437391712214319104)]} 0 0
[junit4:junit4] 2> 170747 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1437391712214319104)]} 0 4
[junit4:junit4] 2> 170748 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[30]} 0 7
[junit4:junit4] 2> 170750 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[31 (1437391712220610560)]} 0 0
[junit4:junit4] 2> 170756 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437391712223756288)]} 0 1
[junit4:junit4] 2> 170756 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[31 (1437391712223756288)]} 0 3
[junit4:junit4] 2> 170759 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[32 (1437391712230047744)]} 0 1
[junit4:junit4] 2> 170764 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437391712233193472)]} 0 0
[junit4:junit4] 2> 170765 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[32 (1437391712233193472)]} 0 4
[junit4:junit4] 2> 170767 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[33 (1437391712238436352)]} 0 0
[junit4:junit4] 2> 170774 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437391712242630656)]} 0 0
[junit4:junit4] 2> 170775 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[33 (1437391712242630656)]} 0 5
[junit4:junit4] 2> 170779 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[34 (1437391712251019264)]} 0 1
[junit4:junit4] 2> 170788 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437391712257310720)]} 0 0
[junit4:junit4] 2> 170790 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[34 (1437391712257310720)]} 0 5
[junit4:junit4] 2> 170791 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[34]} 0 9
[junit4:junit4] 2> 170795 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[35 (1437391712266747904)]} 0 1
[junit4:junit4] 2> 170802 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437391712270942208)]} 0 1
[junit4:junit4] 2> 170803 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[35 (1437391712270942208)]} 0 5
[junit4:junit4] 2> 170807 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[36 (1437391712279330816)]} 0 1
[junit4:junit4] 2> 170815 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437391712284573696)]} 0 1
[junit4:junit4] 2> 170816 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[36 (1437391712284573696)]} 0 5
[junit4:junit4] 2> 170820 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[37 (1437391712294010880)]} 0 0
[junit4:junit4] 2> 170828 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437391712298205184)]} 0 1
[junit4:junit4] 2> 170830 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[37 (1437391712298205184)]} 0 5
[junit4:junit4] 2> 170834 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[38 (1437391712307642368)]} 0 1
[junit4:junit4] 2> 170844 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437391712314982400)]} 0 1
[junit4:junit4] 2> 170846 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1437391712314982400)]} 0 6
[junit4:junit4] 2> 170847 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[38]} 0 10
[junit4:junit4] 2> 170852 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[39 (1437391712326516736)]} 0 1
[junit4:junit4] 2> 170859 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437391712331759616)]} 0 1
[junit4:junit4] 2> 170860 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[39 (1437391712331759616)]} 0 5
[junit4:junit4] 2> 170865 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[40 (1437391712340148224)]} 0 1
[junit4:junit4] 2> 170875 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437391712347488256)]} 0 0
[junit4:junit4] 2> 170876 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1437391712347488256)]} 0 5
[junit4:junit4] 2> 170877 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[40]} 0 9
[junit4:junit4] 2> 170881 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[41 (1437391712356925440)]} 0 1
[junit4:junit4] 2> 170888 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437391712361119744)]} 0 1
[junit4:junit4] 2> 170889 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[41 (1437391712361119744)]} 0 5
[junit4:junit4] 2> 170893 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[42 (1437391712369508352)]} 0 1
[junit4:junit4] 2> 170903 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437391712376848384)]} 0 1
[junit4:junit4] 2> 170904 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1437391712376848384)]} 0 5
[junit4:junit4] 2> 170905 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[42]} 0 9
[junit4:junit4] 2> 170909 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[43 (1437391712387334144)]} 0 1
[junit4:junit4] 2> 170916 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437391712391528448)]} 0 0
[junit4:junit4] 2> 170917 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[43 (1437391712391528448)]} 0 5
[junit4:junit4] 2> 170921 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[44 (1437391712399917056)]} 0 0
[junit4:junit4] 2> 170928 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437391712404111360)]} 0 0
[junit4:junit4] 2> 170930 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[44 (1437391712404111360)]} 0 5
[junit4:junit4] 2> 170933 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[45 (1437391712412499968)]} 0 0
[junit4:junit4] 2> 170943 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437391712419840000)]} 0 1
[junit4:junit4] 2> 170944 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1437391712419840000)]} 0 5
[junit4:junit4] 2> 170946 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[45]} 0 9
[junit4:junit4] 2> 170950 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[46 (1437391712429277184)]} 0 1
[junit4:junit4] 2> 170959 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1437391712436617216)]} 0 0
[junit4:junit4] 2> 170961 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1437391712436617216)]} 0 5
[junit4:junit4] 2> 170962 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[46]} 0 9
[junit4:junit4] 2> 170966 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[47 (1437391712447102976)]} 0 1
[junit4:junit4] 2> 170973 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1437391712451297280)]} 0 1
[junit4:junit4] 2> 170974 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[47 (1437391712451297280)]} 0 5
[junit4:junit4] 2> 170979 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[48 (1437391712459685888)]} 0 1
[junit4:junit4] 2> 170986 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1437391712464928768)]} 0 1
[junit4:junit4] 2> 170987 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[48 (1437391712464928768)]} 0 5
[junit4:junit4] 2> 170991 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[49 (1437391712473317376)]} 0 1
[junit4:junit4] 2> 171001 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1437391712479608832)]} 0 1
[junit4:junit4] 2> 171003 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1437391712479608832)]} 0 6
[junit4:junit4] 2> 171004 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[49]} 0 10
[junit4:junit4] 2> 171008 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[50 (1437391712491143168)]} 0 1
[junit4:junit4] 2> 171014 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1437391712494288896)]} 0 0
[junit4:junit4] 2> 171015 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[50 (1437391712494288896)]} 0 4
[junit4:junit4] 2> 171018 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[51 (1437391712500580352)]} 0 1
[junit4:junit4] 2> 171025 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1437391712505823232)]} 0 0
[junit4:junit4] 2> 171026 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[51 (1437391712505823232)]} 0 4
[junit4:junit4] 2> 171027 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[51]} 0 7
[junit4:junit4] 2> 171030 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[52 (1437391712513163264)]} 0 1
[junit4:junit4] 2> 171036 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1437391712517357568)]} 0 1
[junit4:junit4] 2> 171037 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[52 (1437391712517357568)]} 0 5
[junit4:junit4] 2> 171040 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[53 (1437391712523649024)]} 0 1
[junit4:junit4] 2> 171047 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1437391712528891904)]} 0 1
[junit4:junit4] 2> 171047 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1437391712528891904)]} 0 3
[junit4:junit4] 2> 171048 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[53]} 0 6
[junit4:junit4] 2> 171051 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[54 (1437391712535183360)]} 0 1
[junit4:junit4] 2> 171056 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1437391712538329088)]} 0 1
[junit4:junit4] 2> 171056 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[54 (1437391712538329088)]} 0 3
[junit4:junit4] 2> 171059 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[55 (1437391712544620544)]} 0 1
[junit4:junit4] 2> 171066 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1437391712548814848)]} 0 0
[junit4:junit4] 2> 171067 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1437391712548814848)]} 0 4
[junit4:junit4] 2> 171068 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[55]} 0 7
[junit4:junit4] 2> 171070 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[56 (1437391712556154880)]} 0 0
[junit4:junit4] 2> 171075 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1437391712559300608)]} 0 0
[junit4:junit4] 2> 171076 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[56 (1437391712559300608)]} 0 4
[junit4:junit4] 2> 171079 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[57 (1437391712564543488)]} 0 1
[junit4:junit4] 2> 171085 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1437391712569786368)]} 0 0
[junit4:junit4] 2> 171086 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1437391712569786368)]} 0 3
[junit4:junit4] 2> 171087 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[57]} 0 6
[junit4:junit4] 2> 171089 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[58 (1437391712576077824)]} 0 0
[junit4:junit4] 2> 171095 T437 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1437391712579223552)]} 0 1
[junit4:junit4] 2> 171095 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[58 (1437391712579223552)]} 0 3
[junit4:junit4] 2> 171098 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[59 (1437391712584466432)]} 0 1
[junit4:junit4] 2> 171104 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1437391712588660736)]} 0 1
[junit4:junit4] 2> 171105 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[59 (1437391712588660736)]} 0 5
[junit4:junit4] 2> 171109 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[60 (1437391712597049344)]} 0 1
[junit4:junit4] 2> 171119 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1437391712603340800)]} 0 1
[junit4:junit4] 2> 171120 T402 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1437391712603340800)]} 0 5
[junit4:junit4] 2> 171121 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[60]} 0 9
[junit4:junit4] 2> 171125 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[61 (1437391712612777984)]} 0 1
[junit4:junit4] 2> 171132 T421 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1437391712616972288)]} 0 1
[junit4:junit4] 2> 171134 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[61 (1437391712616972288)]} 0 6
[junit4:junit4] 2> 171138 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[62 (1437391712626409472)]} 0 0
[junit4:junit4] 2> 171144 T435 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1437391712630603776)]} 0 0
[junit4:junit4] 2> 171146 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[62 (1437391712630603776)]} 0 5
[junit4:junit4] 2> 171150 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[63 (1437391712638992384)]} 0 1
[junit4:junit4] 2> 171157 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1437391712645283840)]} 0 0
[junit4:junit4] 2> 171158 T387 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[63 (1437391712645283840)]} 0 3
[junit4:junit4] 2> 171159 T405 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[63]} 0 7
[junit4:junit4] 2> 171162 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[64 (1437391712651575296)]} 0 1
[junit4:junit4] 2> 171168 T419 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1437391712654721024)]} 0 1
[junit4:junit4] 2> 171168 T389 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[64 (1437391712654721024)]} 0 4
[junit4:junit4] 2> 171171 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[65 (1437391712662061056)]} 0 0
[junit4:junit4] 2> 171176 T418 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1437391712665206784)]} 0 0
[junit4:junit4] 2> 171177 T388 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[65 (1437391712665206784)]} 0 3
[junit4:junit4] 2> 171180 T368 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[66 (1437391712671498240)]} 0 1
[junit4:junit4] 2> 171185 T420 C164 P59205 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:53834/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1437391712673595392)]} 0 1
[junit4:junit4] 2> 171186 T386 C166 P53834 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[66 (1437391712673595392)]} 0 4
[junit4:junit4] 2> 171188 T367 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[67 (1437391712679886848)]} 0 0
[junit4:junit4] 2> 171193 T438 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1437391712683032576)]} 0 0
[junit4:junit4] 2> 171194 T403 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[67 (1437391712683032576)]} 0 3
[junit4:junit4] 2> 171197 T366 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[68 (1437391712689324032)]} 0 1
[junit4:junit4] 2> 171203 T436 C165 P37028 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={distrib.from=http://127.0.0.1:47393/jq/ef/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1437391712692469760)]} 0 0
[junit4:junit4] 2> 171204 T404 C167 P47393 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[68 (1437391712692469760)]} 0 4
[junit4:junit4] 2> 171207 T369 C168 P46901 oasup.LogUpdateProcessor.finish [collection1] webapp=/jq/ef path=/update params={wt=javabin&version=2} {add=[69 (1437391712698761216)]} 0 1
[junit4:junit4] 2
[...truncated too long message...]
"core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59205_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59205/jq/ef"}
[junit4:junit4] 2> 314338 T517 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59205_jq%2Fef_collection1_shard1_0_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_0",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_0_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59205_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59205/jq/ef"}
[junit4:junit4] 2> 314342 T517 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59205_jq%2Fef_collection1_shard1_1_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_1_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59205_jq%2Fef",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59205/jq/ef"}
[junit4:junit4] 2> 314345 T442 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> 314346 T351 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/jq/ef,null}
[junit4:junit4] 2> 314398 T351 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37028
[junit4:junit4] 2> 314398 T351 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2084221876
[junit4:junit4] 2> 315400 T351 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 315401 T351 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 315402 T351 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@7a3816b0
[junit4:junit4] 2> 315403 T351 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=655,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 315404 T351 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 315404 T351 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 315404 T351 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 315406 T351 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 315406 T351 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 315406 T351 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index;done=false>>]
[junit4:junit4] 2> 315406 T351 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4/index
[junit4:junit4] 2> 315407 T351 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4;done=false>>]
[junit4:junit4] 2> 315407 T351 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023/jetty4
[junit4:junit4] 2> 315408 T517 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89836980274855948-127.0.0.1:37028_jq%2Fef-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 315431 T351 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/jq/ef,null}
[junit4:junit4] 2> 315486 T351 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 315488 T351 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33858 33858
[junit4:junit4] 2> 315490 T351 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 46901
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370803532023 FAILED !!!!!
[junit4:junit4] 2> 315490 T351 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 315490 T351 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:33858 33858
[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=FD053C3EE7F5A722 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=pl_PL -Dtests.timezone=Africa/Harare -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 171s J1 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:53834/jq/ef returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([FD053C3EE7F5A722:7CE3B22690AAC71E]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 315517 T351 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 171314 T350 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 315624 T425 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 315624 T425 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> 315624 T425 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 316709 T442 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 316709 T442 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> 316710 T442 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=CheapBastard, sim=DefaultSimilarity, locale=pl_PL, timezone=Africa/Harare
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=8,threads=2,free=93672080,total=228655104
[junit4:junit4] 2> NOTE: All tests run in this JVM: [JSONWriterTest, TestBM25SimilarityFactory, TestMergePolicyConfig, TestMultiCoreConfBootstrap, TestAtomicUpdateErrorCases, TestBinaryResponseWriter, TestDFRSimilarityFactory, TestCodecSupport, TestStressReorder, TestArbitraryIndexDir, DocumentAnalysisRequestHandlerTest, URLClassifyProcessorTest, DefaultValueUpdateProcessorTest, SolrIndexConfigTest, FieldAnalysisRequestHandlerTest, TestAddFieldRealTimeGet, TestOmitPositions, TestIndexSearcher, BasicDistributedZk2Test, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 172.60s, 1 test, 1 error <<< FAILURES!
[...truncated 692 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:385: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:365: 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: 296 suites, 1243 tests, 1 error, 13 ignored (7 assumptions)
Total time: 34 minutes 44 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure