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/07 15:59:22 UTC
[JENKINS] Lucene-Solr-trunk-Windows (32bit/jdk1.7.0_21) - Build #
2900 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2900/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:51808/arh 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:51808/arh returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([CFFA791876980FF1:4E1CF70001C76FCD]: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 9999 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 2572881 T6737 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /arh/
[junit4:junit4] 2> 2572886 T6737 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-ChaosMonkeyShardSplitTest-1370613305839
[junit4:junit4] 2> 2572891 T6737 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 2572892 T6738 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 2572990 T6737 oasc.ZkTestServer.run start zk server on port:51789
[junit4:junit4] 2> 2572995 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2573014 T6744 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@188c7b name:ZooKeeperConnection Watcher:127.0.0.1:51789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2573015 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2573015 T6737 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 2573023 T6739 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f1eeb51f90000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 2573024 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2573030 T6746 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d11dec name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2573030 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2573030 T6737 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 2573036 T6737 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 2573042 T6737 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 2573047 T6737 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 2573053 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2573053 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2573063 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 2573064 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 2573070 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2573071 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2573076 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 2573077 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 2573082 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 2573083 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 2573090 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2573090 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2573097 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2573097 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2573105 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2573107 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2573118 T6737 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2573120 T6737 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2573560 T6737 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2573566 T6737 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51796
[junit4:junit4] 2> 2573568 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2573568 T6737 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2573569 T6737 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086
[junit4:junit4] 2> 2573570 T6737 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086\solr.xml
[junit4:junit4] 2> 2573571 T6737 oasc.CoreContainer.<init> New CoreContainer 23008923
[junit4:junit4] 2> 2573572 T6737 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086\'
[junit4:junit4] 2> 2573572 T6737 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086\'
[junit4:junit4] 2> 2573694 T6737 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2573695 T6737 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2573695 T6737 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2573696 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2573696 T6737 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2573696 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2573697 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2573697 T6737 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2573698 T6737 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2573698 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2573706 T6737 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2573706 T6737 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51789/solr
[junit4:junit4] 2> 2573707 T6737 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2573709 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2573728 T6757 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dd12ba name:ZooKeeperConnection Watcher:127.0.0.1:51789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2573729 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2573733 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2573745 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2573750 T6759 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19dae3f name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2573750 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2573754 T6737 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 2573761 T6737 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 2573767 T6737 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 2573773 T6737 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51796_arh
[junit4:junit4] 2> 2573776 T6737 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51796_arh
[junit4:junit4] 2> 2573785 T6737 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 2573799 T6737 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 2573803 T6737 oasc.Overseer.start Overseer (id=89824513612120067-127.0.0.1:51796_arh-n_0000000000) starting
[junit4:junit4] 2> 2573811 T6737 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 2573819 T6761 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 2573820 T6737 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 2573825 T6737 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 2573830 T6737 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2573834 T6760 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 2573840 T6762 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086\collection1
[junit4:junit4] 2> 2573841 T6762 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 2573842 T6762 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2573842 T6762 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 2573846 T6762 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086\collection1\'
[junit4:junit4] 2> 2573848 T6762 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2573848 T6762 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086/collection1/lib/README' to classloader
[junit4:junit4] 2> 2573909 T6762 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 2573977 T6762 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2573979 T6762 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2573986 T6762 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2574625 T6762 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2574629 T6762 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2574631 T6762 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2574637 T6762 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2574671 T6762 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2574671 T6762 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370613306086\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/control/data\
[junit4:junit4] 2> 2574671 T6762 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@750372
[junit4:junit4] 2> 2574672 T6762 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2574672 T6762 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/control/data\
[junit4:junit4] 2> 2574673 T6762 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/control/data\index/
[junit4:junit4] 2> 2574673 T6762 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2574674 T6762 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/control/data\index
[junit4:junit4] 2> 2574679 T6762 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9126c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d77bb4),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2574680 T6762 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2574682 T6762 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2574682 T6762 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2574683 T6762 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2574684 T6762 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2574684 T6762 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2574684 T6762 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2574686 T6762 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2574686 T6762 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2574687 T6762 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2574703 T6762 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2574712 T6762 oass.SolrIndexSearcher.<init> Opening Searcher@148f3f0 main
[junit4:junit4] 2> 2574713 T6762 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\control\data\tlog
[junit4:junit4] 2> 2574715 T6762 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2574715 T6762 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2574723 T6763 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@148f3f0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2574725 T6762 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2574725 T6762 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2575313 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2575315 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51796_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51796/arh"}
[junit4:junit4] 2> 2575316 T6760 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2575316 T6760 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2575337 T6759 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> 2575708 T6762 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2575708 T6762 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51796/arh collection:control_collection shard:shard1
[junit4:junit4] 2> 2575709 T6762 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2575730 T6762 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2575735 T6762 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2575735 T6762 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2575735 T6762 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51796/arh/collection1/
[junit4:junit4] 2> 2575736 T6762 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2575736 T6762 oasc.SyncStrategy.syncToMe http://127.0.0.1:51796/arh/collection1/ has no replicas
[junit4:junit4] 2> 2575736 T6762 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51796/arh/collection1/
[junit4:junit4] 2> 2575737 T6762 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2576820 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2576835 T6759 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> 2576845 T6762 oasc.ZkController.register We are http://127.0.0.1:51796/arh/collection1/ and leader is http://127.0.0.1:51796/arh/collection1/
[junit4:junit4] 2> 2576845 T6762 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51796/arh
[junit4:junit4] 2> 2576846 T6762 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2576846 T6762 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2576846 T6762 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2576849 T6762 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2576851 T6737 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2576852 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2576852 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2576860 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2576863 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2576868 T6766 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@136c61f name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2576868 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2576869 T6737 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2576874 T6737 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 2577300 T6737 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2577306 T6737 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51808
[junit4:junit4] 2> 2577307 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2577308 T6737 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2577308 T6737 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825
[junit4:junit4] 2> 2577309 T6737 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825\solr.xml
[junit4:junit4] 2> 2577310 T6737 oasc.CoreContainer.<init> New CoreContainer 1979988
[junit4:junit4] 2> 2577310 T6737 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825\'
[junit4:junit4] 2> 2577311 T6737 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825\'
[junit4:junit4] 2> 2577451 T6737 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2577451 T6737 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2577452 T6737 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2577452 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2577453 T6737 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2577453 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2577454 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2577454 T6737 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2577454 T6737 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2577455 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2577463 T6737 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2577464 T6737 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51789/solr
[junit4:junit4] 2> 2577464 T6737 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2577466 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2577481 T6777 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dd9198 name:ZooKeeperConnection Watcher:127.0.0.1:51789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2577481 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2577486 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2577492 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2577496 T6779 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ed5498 name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2577496 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2577503 T6737 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2578364 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2578366 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51796_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51796/arh"}
[junit4:junit4] 2> 2578377 T6779 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> 2578378 T6759 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> 2578377 T6766 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> 2578552 T6737 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51808_arh
[junit4:junit4] 2> 2578557 T6737 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51808_arh
[junit4:junit4] 2> 2578565 T6779 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2578565 T6779 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> 2578566 T6766 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2578566 T6759 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2578566 T6759 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> 2578566 T6766 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> 2578582 T6780 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825\collection1
[junit4:junit4] 2> 2578582 T6780 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2578583 T6780 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2578584 T6780 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2578587 T6780 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825\collection1\'
[junit4:junit4] 2> 2578589 T6780 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2578590 T6780 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825/collection1/lib/README' to classloader
[junit4:junit4] 2> 2578660 T6780 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 2578740 T6780 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2578742 T6780 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2578748 T6780 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2579540 T6780 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2579545 T6780 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2579548 T6780 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2579558 T6780 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2579602 T6780 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2579603 T6780 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370613309825\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty1\
[junit4:junit4] 2> 2579603 T6780 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@750372
[junit4:junit4] 2> 2579603 T6780 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2579604 T6780 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty1\
[junit4:junit4] 2> 2579604 T6780 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty1\index/
[junit4:junit4] 2> 2579605 T6780 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2579605 T6780 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty1\index
[junit4:junit4] 2> 2579611 T6780 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c51883 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a26d60),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2579612 T6780 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2579616 T6780 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2579616 T6780 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2579617 T6780 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2579618 T6780 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2579619 T6780 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2579619 T6780 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2579619 T6780 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2579620 T6780 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2579621 T6780 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2579634 T6780 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2579642 T6780 oass.SolrIndexSearcher.<init> Opening Searcher@1c9f06b main
[junit4:junit4] 2> 2579643 T6780 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty1\tlog
[junit4:junit4] 2> 2579645 T6780 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2579645 T6780 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2579651 T6781 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c9f06b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2579655 T6780 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2579655 T6780 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2580003 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2580005 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51808_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51808/arh"}
[junit4:junit4] 2> 2580005 T6760 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 2580005 T6760 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2580018 T6759 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> 2580018 T6779 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> 2580018 T6766 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> 2580738 T6780 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2580738 T6780 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51808/arh collection:collection1 shard:shard1
[junit4:junit4] 2> 2580739 T6780 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 2580762 T6780 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2580769 T6780 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2580769 T6780 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2580770 T6780 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51808/arh/collection1/
[junit4:junit4] 2> 2580770 T6780 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2580770 T6780 oasc.SyncStrategy.syncToMe http://127.0.0.1:51808/arh/collection1/ has no replicas
[junit4:junit4] 2> 2580771 T6780 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51808/arh/collection1/
[junit4:junit4] 2> 2580771 T6780 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 2581648 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2581672 T6759 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> 2581673 T6779 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> 2581672 T6766 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> 2581721 T6780 oasc.ZkController.register We are http://127.0.0.1:51808/arh/collection1/ and leader is http://127.0.0.1:51808/arh/collection1/
[junit4:junit4] 2> 2581721 T6780 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51808/arh
[junit4:junit4] 2> 2581721 T6780 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2581721 T6780 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2581721 T6780 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2581727 T6780 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2581729 T6737 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2581729 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2581730 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2582196 T6737 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2582203 T6737 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51817
[junit4:junit4] 2> 2582205 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2582205 T6737 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2582205 T6737 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691
[junit4:junit4] 2> 2582205 T6737 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691\solr.xml
[junit4:junit4] 2> 2582206 T6737 oasc.CoreContainer.<init> New CoreContainer 10061936
[junit4:junit4] 2> 2582207 T6737 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691\'
[junit4:junit4] 2> 2582207 T6737 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691\'
[junit4:junit4] 2> 2582344 T6737 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2582345 T6737 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2582345 T6737 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2582346 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2582346 T6737 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2582346 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2582347 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2582347 T6737 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2582348 T6737 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2582348 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2582357 T6737 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2582357 T6737 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51789/solr
[junit4:junit4] 2> 2582357 T6737 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2582360 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2582371 T6793 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@577058 name:ZooKeeperConnection Watcher:127.0.0.1:51789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2582372 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2582375 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2582383 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2582388 T6795 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@190d8a7 name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2582388 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2582396 T6737 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2583304 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2583305 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51808_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51808/arh"}
[junit4:junit4] 2> 2583317 T6795 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> 2583319 T6759 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> 2583319 T6766 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> 2583320 T6779 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> 2583481 T6737 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51817_arh
[junit4:junit4] 2> 2583484 T6737 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51817_arh
[junit4:junit4] 2> 2583493 T6795 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2583493 T6795 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> 2583495 T6766 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2583495 T6766 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> 2583495 T6779 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2583496 T6779 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> 2583495 T6759 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2583496 T6759 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> 2583509 T6796 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691\collection1
[junit4:junit4] 2> 2583510 T6796 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2583511 T6796 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2583511 T6796 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2583514 T6796 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691\collection1\'
[junit4:junit4] 2> 2583516 T6796 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2583517 T6796 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691/collection1/lib/README' to classloader
[junit4:junit4] 2> 2583581 T6796 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 2583659 T6796 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2583662 T6796 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2583668 T6796 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2584380 T6796 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2584385 T6796 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2584387 T6796 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2584394 T6796 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2584441 T6796 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2584442 T6796 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370613314691\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty2\
[junit4:junit4] 2> 2584442 T6796 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@750372
[junit4:junit4] 2> 2584442 T6796 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2584443 T6796 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty2\
[junit4:junit4] 2> 2584443 T6796 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty2\index/
[junit4:junit4] 2> 2584443 T6796 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2584444 T6796 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty2\index
[junit4:junit4] 2> 2584448 T6796 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c0037 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec74f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2584449 T6796 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2584453 T6796 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2584453 T6796 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2584454 T6796 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2584456 T6796 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2584456 T6796 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2584457 T6796 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2584457 T6796 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2584458 T6796 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2584458 T6796 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2584469 T6796 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2584479 T6796 oass.SolrIndexSearcher.<init> Opening Searcher@133f783 main
[junit4:junit4] 2> 2584480 T6796 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty2\tlog
[junit4:junit4] 2> 2584482 T6796 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2584482 T6796 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2584488 T6797 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@133f783 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2584490 T6796 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2584490 T6796 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2584946 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2584948 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51817_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51817/arh"}
[junit4:junit4] 2> 2584948 T6760 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2584948 T6760 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2584959 T6779 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> 2584960 T6795 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> 2584961 T6759 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> 2584960 T6766 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> 2585576 T6796 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2585577 T6796 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51817/arh collection:collection1 shard:shard2
[junit4:junit4] 2> 2585579 T6796 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 2585609 T6796 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2585622 T6796 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2585623 T6796 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2585623 T6796 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51817/arh/collection1/
[junit4:junit4] 2> 2585625 T6796 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2585626 T6796 oasc.SyncStrategy.syncToMe http://127.0.0.1:51817/arh/collection1/ has no replicas
[junit4:junit4] 2> 2585626 T6796 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51817/arh/collection1/
[junit4:junit4] 2> 2585627 T6796 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2586587 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2586612 T6779 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> 2586613 T6795 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> 2586613 T6759 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> 2586614 T6766 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> 2586647 T6796 oasc.ZkController.register We are http://127.0.0.1:51817/arh/collection1/ and leader is http://127.0.0.1:51817/arh/collection1/
[junit4:junit4] 2> 2586647 T6796 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51817/arh
[junit4:junit4] 2> 2586647 T6796 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2586649 T6796 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2586649 T6796 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2586652 T6796 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2586655 T6737 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2586655 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2586656 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2587130 T6737 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2587136 T6737 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51826
[junit4:junit4] 2> 2587137 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2587137 T6737 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2587139 T6737 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615
[junit4:junit4] 2> 2587139 T6737 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615\solr.xml
[junit4:junit4] 2> 2587139 T6737 oasc.CoreContainer.<init> New CoreContainer 13990245
[junit4:junit4] 2> 2587140 T6737 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615\'
[junit4:junit4] 2> 2587140 T6737 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615\'
[junit4:junit4] 2> 2587270 T6737 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2587270 T6737 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2587271 T6737 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2587271 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2587271 T6737 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2587271 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2587272 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2587273 T6737 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2587274 T6737 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2587274 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2587283 T6737 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2587283 T6737 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51789/solr
[junit4:junit4] 2> 2587284 T6737 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2587288 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2587307 T6809 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d73a45 name:ZooKeeperConnection Watcher:127.0.0.1:51789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2587307 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2587311 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2587319 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2587323 T6811 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43af6b name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2587324 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2587333 T6737 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2588246 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2588247 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51817_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51817/arh"}
[junit4:junit4] 2> 2588260 T6811 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> 2588260 T6779 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> 2588261 T6795 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> 2588260 T6766 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> 2588262 T6759 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> 2588416 T6737 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51826_arh
[junit4:junit4] 2> 2588419 T6737 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51826_arh
[junit4:junit4] 2> 2588427 T6811 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2588428 T6811 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> 2588428 T6766 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2588429 T6795 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2588429 T6795 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> 2588429 T6766 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> 2588429 T6759 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2588432 T6759 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> 2588429 T6779 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2588432 T6779 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> 2588447 T6812 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615\collection1
[junit4:junit4] 2> 2588448 T6812 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2588449 T6812 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2588449 T6812 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2588452 T6812 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615\collection1\'
[junit4:junit4] 2> 2588454 T6812 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2588455 T6812 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615/collection1/lib/README' to classloader
[junit4:junit4] 2> 2588528 T6812 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 2588608 T6812 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2588611 T6812 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2588616 T6812 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2589290 T6812 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2589295 T6812 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2589298 T6812 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2589305 T6812 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2589343 T6812 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2589343 T6812 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370613319615\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\
[junit4:junit4] 2> 2589344 T6812 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@750372
[junit4:junit4] 2> 2589344 T6812 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2589345 T6812 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\
[junit4:junit4] 2> 2589345 T6812 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index/
[junit4:junit4] 2> 2589345 T6812 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2589346 T6812 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index
[junit4:junit4] 2> 2589350 T6812 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1923927 lockFactory=org.apache.lucene.store.NativeFSLockFactory@92e571),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2589351 T6812 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2589354 T6812 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2589354 T6812 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2589356 T6812 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2589356 T6812 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2589364 T6812 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2589365 T6812 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2589365 T6812 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2589367 T6812 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2589367 T6812 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2589378 T6812 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2589386 T6812 oass.SolrIndexSearcher.<init> Opening Searcher@18d6ea main
[junit4:junit4] 2> 2589386 T6812 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty3\tlog
[junit4:junit4] 2> 2589388 T6812 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2589388 T6812 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2589394 T6813 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18d6ea main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2589396 T6812 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2589396 T6812 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2589801 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2589802 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51826_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51826/arh"}
[junit4:junit4] 2> 2589803 T6760 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2589803 T6760 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2589813 T6811 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> 2589814 T6766 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> 2589815 T6759 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> 2589814 T6795 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> 2589814 T6779 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> 2590404 T6812 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2590404 T6812 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51826/arh collection:collection1 shard:shard1
[junit4:junit4] 2> 2590446 T6812 oasc.ZkController.register We are http://127.0.0.1:51826/arh/collection1/ and leader is http://127.0.0.1:51808/arh/collection1/
[junit4:junit4] 2> 2590447 T6812 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51826/arh
[junit4:junit4] 2> 2590448 T6812 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2590449 T6812 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C10959 name=collection1 org.apache.solr.core.SolrCore@d97307 url=http://127.0.0.1:51826/arh/collection1 node=127.0.0.1:51826_arh C10959_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51826_arh, base_url=http://127.0.0.1:51826/arh}
[junit4:junit4] 2> 2590451 T6814 C10959 P51826 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2590453 T6814 C10959 P51826 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2590455 T6814 C10959 P51826 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2590456 T6814 C10959 P51826 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2590456 T6812 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2590465 T6814 C10959 P51826 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2590469 T6737 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2590471 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2590472 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2590499 T6775 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2590936 T6737 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2590942 T6737 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51836
[junit4:junit4] 2> 2590945 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2590945 T6737 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2590945 T6737 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444
[junit4:junit4] 2> 2590946 T6737 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444\solr.xml
[junit4:junit4] 2> 2590946 T6737 oasc.CoreContainer.<init> New CoreContainer 22282400
[junit4:junit4] 2> 2590947 T6737 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444\'
[junit4:junit4] 2> 2590948 T6737 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444\'
[junit4:junit4] 2> 2591066 T6737 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2591068 T6737 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2591070 T6737 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2591070 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2591070 T6737 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2591071 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2591071 T6737 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2591072 T6737 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2591072 T6737 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2591073 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2591081 T6737 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2591081 T6737 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51789/solr
[junit4:junit4] 2> 2591084 T6737 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2591085 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2591099 T6826 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@116d45 name:ZooKeeperConnection Watcher:127.0.0.1:51789 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2591099 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2591104 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2591111 T6737 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2591115 T6828 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1620e28 name:ZooKeeperConnection Watcher:127.0.0.1:51789/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2591115 T6737 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2591171 T6737 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2591328 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2591329 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51826_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51826/arh"}
[junit4:junit4] 2> 2591339 T6779 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> 2591339 T6811 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> 2591339 T6766 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> 2591339 T6828 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> 2591340 T6759 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> 2591340 T6795 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> 2591499 T6775 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2591500 T6775 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:51826_arh&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 2592178 T6737 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51836_arh
[junit4:junit4] 2> 2592182 T6737 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51836_arh
[junit4:junit4] 2> 2592193 T6828 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> 2592194 T6811 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2592195 T6811 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> 2592196 T6766 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2592196 T6766 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> 2592195 T6779 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2592198 T6779 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> 2592197 T6759 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2592199 T6759 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> 2592197 T6795 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2592200 T6795 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> 2592206 T6828 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2592212 T6829 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444\collection1
[junit4:junit4] 2> 2592213 T6829 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2592214 T6829 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2592214 T6829 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2592217 T6829 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444\collection1\'
[junit4:junit4] 2> 2592219 T6829 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2592220 T6829 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444/collection1/lib/README' to classloader
[junit4:junit4] 2> 2592286 T6829 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 2592360 T6829 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2592362 T6829 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2592368 T6829 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2593055 T6829 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2593059 T6829 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2593061 T6829 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2593079 T6829 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2593121 T6829 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2593121 T6829 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370613323444\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\
[junit4:junit4] 2> 2593121 T6829 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@750372
[junit4:junit4] 2> 2593122 T6829 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2593123 T6829 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\
[junit4:junit4] 2> 2593123 T6829 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index/
[junit4:junit4] 2> 2593123 T6829 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2593123 T6829 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index
[junit4:junit4] 2> 2593127 T6829 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@134b5c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10b4535),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2593127 T6829 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2593131 T6829 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2593131 T6829 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2593133 T6829 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2593134 T6829 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2593135 T6829 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2593135 T6829 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2593135 T6829 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2593136 T6829 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2593136 T6829 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2593150 T6829 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2593157 T6829 oass.SolrIndexSearcher.<init> Opening Searcher@655db2 main
[junit4:junit4] 2> 2593157 T6829 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837\jetty4\tlog
[junit4:junit4] 2> 2593159 T6829 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2593159 T6829 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2593165 T6830 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@655db2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2593167 T6829 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2593167 T6829 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C10960 name=collection1 org.apache.solr.core.SolrCore@d97307 url=http://127.0.0.1:51826/arh/collection1 node=127.0.0.1:51826_arh C10960_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51826_arh, base_url=http://127.0.0.1:51826/arh}
[junit4:junit4] 2> 2593501 T6814 C10960 P51826 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51808/arh/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2593502 T6814 C10960 P51826 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51826/arh START replicas=[http://127.0.0.1:51808/arh/collection1/] nUpdates=100
[junit4:junit4] 2> 2593503 T6814 C10960 P51826 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2593504 T6814 C10960 P51826 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2593505 T6814 C10960 P51826 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2593505 T6814 C10960 P51826 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2593506 T6814 C10960 P51826 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2593507 T6814 C10960 P51826 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51808/arh/collection1/. core=collection1
[junit4:junit4] 2> 2593508 T6814 C10960 P51826 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C10961 name=collection1 org.apache.solr.core.SolrCore@27702b url=http://127.0.0.1:51808/arh/collection1 node=127.0.0.1:51808_arh C10961_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51808_arh, base_url=http://127.0.0.1:51808/arh, leader=true}
[junit4:junit4] 2> 2593522 T6775 C10961 P51808 oasc.SolrCore.execute [collection1] webapp=/arh path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 2593525 T6770 C10961 P51808 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2593528 T6770 C10961 P51808 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c51883 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a26d60),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2593529 T6770 C10961 P51808 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2593530 T6770 C10961 P51808 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c51883 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a26d60),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c51883 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a26d60),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2593530 T6770 C10961 P51808 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2593531 T6770 C10961 P51808 oass.SolrIndexSearcher.<init> Opening Searcher@1783e9b realtime
[junit4:junit4] 2> 2593531 T6770 C10961 P51808 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2593532 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh 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> 2593532 T6814 C10960 P51826 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2593533 T6814 C10960 P51826 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2593536 T6773 C10961 P51808 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2593536 T6773 C10961 P51808 oasc.SolrCore.execute [collection1] webapp=/arh path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 2593537 T6814 C10960 P51826 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2593537 T6814 C10960 P51826 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2593537 T6814 C10960 P51826 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2593540 T6774 C10961 P51808 oasc.SolrCore.execute [collection1] webapp=/arh path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 2593540 T6814 C10960 P51826 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2593541 T6814 C10960 P51826 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index.20130607235526490
[junit4:junit4] 2> 2593542 T6814 C10960 P51826 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@28aed2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39804d) fullCopy=false
[junit4:junit4] 2> 2593544 T6771 C10961 P51808 oasc.SolrCore.execute [collection1] webapp=/arh path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 2593546 T6814 C10960 P51826 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2593547 T6814 C10960 P51826 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2593547 T6814 C10960 P51826 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 2593552 T6814 C10960 P51826 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1923927 lockFactory=org.apache.lucene.store.NativeFSLockFactory@92e571),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1923927 lockFactory=org.apache.lucene.store.NativeFSLockFactory@92e571),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2593553 T6814 C10960 P51826 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2593553 T6814 C10960 P51826 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2593553 T6814 C10960 P51826 oass.SolrIndexSearcher.<init> Opening Searcher@5e4855 main
[junit4:junit4] 2> 2593554 T6813 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e4855 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2593555 T6814 C10960 P51826 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index.20130607235526490 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index.20130607235526490;done=true>>]
[junit4:junit4] 2> 2593555 T6814 C10960 P51826 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index.20130607235526490
[junit4:junit4] 2> 2593555 T6814 C10960 P51826 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty3\index.20130607235526490
[junit4:junit4] 2> 2593555 T6814 C10960 P51826 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2593555 T6814 C10960 P51826 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2593556 T6814 C10960 P51826 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2593556 T6814 C10960 P51826 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2593559 T6814 C10960 P51826 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2594354 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2594356 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51836_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51836/arh"}
[junit4:junit4] 2> 2594357 T6760 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2594358 T6760 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2594373 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51826_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51826/arh"}
[junit4:junit4] 2> 2594381 T6779 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> 2594381 T6766 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> 2594381 T6759 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> 2594381 T6795 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> 2594381 T6811 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> 2594381 T6828 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> 2595176 T6829 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2595176 T6829 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51836/arh collection:collection1 shard:shard2
[junit4:junit4] 2> 2595192 T6829 oasc.ZkController.register We are http://127.0.0.1:51836/arh/collection1/ and leader is http://127.0.0.1:51817/arh/collection1/
[junit4:junit4] 2> 2595193 T6829 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51836/arh
[junit4:junit4] 2> 2595194 T6829 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2595194 T6829 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C10962 name=collection1 org.apache.solr.core.SolrCore@72a379 url=http://127.0.0.1:51836/arh/collection1 node=127.0.0.1:51836_arh C10962_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51836_arh, base_url=http://127.0.0.1:51836/arh}
[junit4:junit4] 2> 2595197 T6833 C10962 P51836 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2595198 T6829 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2595199 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2595200 T6833 C10962 P51836 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2595201 T6833 C10962 P51836 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2595203 T6737 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2595205 T6737 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2595206 T6737 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2595206 T6833 C10962 P51836 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2595220 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2595223 T6788 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2595223 T6737 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 2595225 T6737 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 2595228 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2595894 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2595895 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51836_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51836/arh"}
[junit4:junit4] 2> 2595907 T6828 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> 2595907 T6766 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> 2595907 T6759 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> 2595907 T6811 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> 2595907 T6795 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> 2595907 T6779 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> 2596224 T6788 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2596224 T6788 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:51836_arh&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 2596231 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2597233 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C10962_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51836_arh, base_url=http://127.0.0.1:51836/arh}
[junit4:junit4] 2> 2598225 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51817/arh/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2598225 T6833 C10962 P51836 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51836/arh START replicas=[http://127.0.0.1:51817/arh/collection1/] nUpdates=100
[junit4:junit4] 2> 2598226 T6833 C10962 P51836 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2598226 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2598227 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2598228 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2598228 T6833 C10962 P51836 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2598228 T6833 C10962 P51836 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51817/arh/collection1/. core=collection1
[junit4:junit4] 2> 2598228 T6833 C10962 P51836 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2598240 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C10963 name=collection1 org.apache.solr.core.SolrCore@dc696 url=http://127.0.0.1:51817/arh/collection1 node=127.0.0.1:51817_arh C10963_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51817_arh, base_url=http://127.0.0.1:51817/arh, leader=true}
[junit4:junit4] 2> 2598242 T6788 C10963 P51817 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2598242 T6790 C10963 P51817 oasc.SolrCore.execute [collection1] webapp=/arh path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 2598247 T6788 C10963 P51817 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c0037 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec74f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2598248 T6788 C10963 P51817 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2598248 T6788 C10963 P51817 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c0037 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec74f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c0037 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec74f3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2598248 T6788 C10963 P51817 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2598249 T6788 C10963 P51817 oass.SolrIndexSearcher.<init> Opening Searcher@1028c2f realtime
[junit4:junit4] 2> 2598249 T6788 C10963 P51817 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2598250 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 2598251 T6833 C10962 P51836 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2598252 T6833 C10962 P51836 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2598254 T6791 C10963 P51817 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2598255 T6791 C10963 P51817 oasc.SolrCore.execute [collection1] webapp=/arh path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 2598256 T6833 C10962 P51836 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2598256 T6833 C10962 P51836 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2598256 T6833 C10962 P51836 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2598258 T6786 C10963 P51817 oasc.SolrCore.execute [collection1] webapp=/arh path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 2598259 T6833 C10962 P51836 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2598260 T6833 C10962 P51836 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index.20130607235531209
[junit4:junit4] 2> 2598260 T6833 C10962 P51836 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e24ae0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d491e9) fullCopy=false
[junit4:junit4] 2> 2598262 T6789 C10963 P51817 oasc.SolrCore.execute [collection1] webapp=/arh path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 2598264 T6833 C10962 P51836 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2598265 T6833 C10962 P51836 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2598265 T6833 C10962 P51836 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 2598267 T6833 C10962 P51836 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@134b5c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10b4535),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@134b5c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10b4535),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2598269 T6833 C10962 P51836 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2598269 T6833 C10962 P51836 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2598269 T6833 C10962 P51836 oass.SolrIndexSearcher.<init> Opening Searcher@10f1754 main
[junit4:junit4] 2> 2598270 T6830 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10f1754 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2598271 T6833 C10962 P51836 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index.20130607235531209 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index.20130607235531209;done=true>>]
[junit4:junit4] 2> 2598271 T6833 C10962 P51836 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index.20130607235531209
[junit4:junit4] 2> 2598271 T6833 C10962 P51836 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370613305837/jetty4\index.20130607235531209
[junit4:junit4] 2> 2598272 T6833 C10962 P51836 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2598272 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2598272 T6833 C10962 P51836 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2598272 T6833 C10962 P51836 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2598285 T6833 C10962 P51836 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2598923 T6760 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2598924 T6760 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51836_arh",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51836/arh"}
[junit4:junit4] 2> 2598935 T6828 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> 2598935 T6779 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> 2598936 T6811 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> 2598937 T6795 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> 2598936 T6766 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> 2598937 T6759 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> 2599244 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2599247 T6737 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C10964 name=collection1 org.apache.solr.core.SolrCore@1e01fe8 url=http://127.0.0.1:51796/arh/collection1 node=127.0.0.1:51796_arh C10964_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51796_arh, base_url=http://127.0.0.1:51796/arh, leader=true}
[junit4:junit4] 2> 2599255 T6755 C10964 P51796 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2599260 T6755 C10964 P51796 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9126c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d77bb4),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2599261 T6755 C10964 P51796 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2599262 T6755 C10964 P51796 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9126c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d77bb4),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9126c0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d77bb4),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2599262 T6755 C10964 P51796 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2599262 T6755 C10964 P51796 oass.SolrIndexSearcher.<init> Opening Searcher@946b49 main
[junit4:junit4] 2> 2599263 T6755 C10964 P51796 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2599264 T6763 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@946b49 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2599265 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 2599272 T6787 C10963 P51817 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2599273 T6787 C10963 P51817 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c0037 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec74f3),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c0037 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec74f3),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2599274 T6787 C10963 P51817 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2599274 T6787 C10963 P51817 oass.SolrIndexSearcher.<init> Opening Searcher@1af715d main
[junit4:junit4] 2> 2599275 T6787 C10963 P51817 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2599275 T6797 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1af715d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2599277 T6787 C10963 P51817 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51808/arh/collection1/, StdNode: http://127.0.0.1:51826/arh/collection1/, StdNode: http://127.0.0.1:51836/arh/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 2599284 T6773 C10961 P51808 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2599286 T6773 C10961 P51808 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c51883 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a26d60),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c51883 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a26d60),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2599286 T6773 C10961 P51808 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2599287 T6773 C10961 P51808 oass.SolrIndexSearcher.<init> Opening Searcher@172af4d main
[junit4:junit4] 2> 2599287 T6773 C10961 P51808 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2599289 T6781 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@172af4d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2599290 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> C10962_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51836_arh, base_url=http://127.0.0.1:51836/arh}
[junit4:junit4] 2> 2599298 T6820 C10962 P51836 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2599300 T6820 C10962 P51836 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@134b5c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10b4535),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@134b5c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10b4535),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2599301 T6820 C10962 P51836 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2599302 T6820 C10962 P51836 oass.SolrIndexSearcher.<init> Opening Searcher@1087de0 main
[junit4:junit4] 2> 2599303 T6820 C10962 P51836 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> C10960_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51826_arh, base_url=http://127.0.0.1:51826/arh}
[junit4:junit4] 2> 2599305 T6806 C10960 P51826 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2599305 T6830 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1087de0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2599306 T6806 C10960 P51826 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1923927 lockFactory=org.apache.lucene.store.NativeFSLockFactory@92e571),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1923927 lockFactory=org.apache.lucene.store.NativeFSLockFactory@92e571),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2599307 T6806 C10960 P51826 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2599307 T6820 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 2599308 T6806 C10960 P51826 oass.SolrIndexSearcher.<init> Opening Searcher@2d656c main
[junit4:junit4] 2> 2599309 T6806 C10960 P51826 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2599310 T6813 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d656c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2599310 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 2599312 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 40
[junit4:junit4] 2> 2599313 T6737 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2599317 T6774 C10961 P51808 oasc.SolrCore.execute [collection1] webapp=/arh path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 2599319 T6805 C10960 P51826 oasc.SolrCore.execute [collection1] webapp=/arh path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 2599322 T6791 C10963 P51817 oasc.SolrCore.execute [collection1] webapp=/arh path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 2599324 T6821 C10962 P51836 oasc.SolrCore.execute [collection1] webapp=/arh path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 2601331 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437192247603888128)} 0 3
[junit4:junit4] 2> 2601340 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={update.distrib=FROMLEADER&_version_=-1437192247609131008&update.from=http://127.0.0.1:51808/arh/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437192247609131008)} 0 2
[junit4:junit4] 2> 2601345 T6819 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={update.distrib=FROMLEADER&_version_=-1437192247615422464&update.from=http://127.0.0.1:51817/arh/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437192247615422464)} 0 3
[junit4:junit4] 2> 2601347 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437192247615422464)} 0 9
[junit4:junit4] 2> 2601348 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437192247609131008)} 0 15
[junit4:junit4] 2> 2601350 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[0 (1437192247626956800)]} 0 0
[junit4:junit4] 2> 2601359 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1437192247632199680)]} 0 1
[junit4:junit4] 2> 2601360 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1437192247632199680)]} 0 5
[junit4:junit4] 2> 2601361 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[0]} 0 8
[junit4:junit4] 2> 2601365 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[1 (1437192247642685440)]} 0 0
[junit4:junit4] 2> 2601371 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1437192247645831168)]} 0 0
[junit4:junit4] 2> 2601372 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[1 (1437192247645831168)]} 0 4
[junit4:junit4] 2> 2601374 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[2 (1437192247652122624)]} 0 0
[junit4:junit4] 2> 2601383 T6820 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1437192247657365504)]} 0 1
[junit4:junit4] 2> 2601384 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1437192247657365504)]} 0 5
[junit4:junit4] 2> 2601385 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[2]} 0 8
[junit4:junit4] 2> 2601388 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[3 (1437192247666802688)]} 0 0
[junit4:junit4] 2> 2601398 T6821 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1437192247674142720)]} 0 0
[junit4:junit4] 2> 2601399 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1437192247674142720)]} 0 4
[junit4:junit4] 2> 2601400 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[3]} 0 8
[junit4:junit4] 2> 2601403 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[4 (1437192247682531328)]} 0 0
[junit4:junit4] 2> 2601411 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1437192247686725632)]} 0 1
[junit4:junit4] 2> 2601412 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[4 (1437192247686725632)]} 0 5
[junit4:junit4] 2> 2601415 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[5 (1437192247695114240)]} 0 0
[junit4:junit4] 2> 2601424 T6822 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1437192247701405696)]} 0 0
[junit4:junit4] 2> 2601425 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1437192247701405696)]} 0 4
[junit4:junit4] 2> 2601426 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[5]} 0 8
[junit4:junit4] 2> 2601429 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[6 (1437192247709794304)]} 0 0
[junit4:junit4] 2> 2601437 T6823 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1437192247712940032)]} 0 1
[junit4:junit4] 2> 2601438 T6790 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[6 (1437192247712940032)]} 0 6
[junit4:junit4] 2> 2601441 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[7 (1437192247722377216)]} 0 0
[junit4:junit4] 2> 2601450 T6824 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1437192247727620096)]} 0 1
[junit4:junit4] 2> 2601451 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1437192247727620096)]} 0 5
[junit4:junit4] 2> 2601452 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[7]} 0 8
[junit4:junit4] 2> 2601456 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[8 (1437192247738105856)]} 0 0
[junit4:junit4] 2> 2601467 T6803 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1437192247745445888)]} 0 1
[junit4:junit4] 2> 2601468 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1437192247745445888)]} 0 5
[junit4:junit4] 2> 2601469 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[8]} 0 8
[junit4:junit4] 2> 2601473 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[9 (1437192247755931648)]} 0 0
[junit4:junit4] 2> 2601480 T6819 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1437192247759077376)]} 0 1
[junit4:junit4] 2> 2601481 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[9 (1437192247759077376)]} 0 5
[junit4:junit4] 2> 2601485 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[10 (1437192247767465984)]} 0 1
[junit4:junit4] 2> 2601493 T6804 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437192247772708864)]} 0 1
[junit4:junit4] 2> 2601494 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[10 (1437192247772708864)]} 0 5
[junit4:junit4] 2> 2601497 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[11 (1437192247781097472)]} 0 0
[junit4:junit4] 2> 2601506 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437192247786340352)]} 0 1
[junit4:junit4] 2> 2601507 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1437192247786340352)]} 0 5
[junit4:junit4] 2> 2601508 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[11]} 0 8
[junit4:junit4] 2> 2601510 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[12 (1437192247794728960)]} 0 0
[junit4:junit4] 2> 2601519 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437192247799971840)]} 0 1
[junit4:junit4] 2> 2601520 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1437192247799971840)]} 0 5
[junit4:junit4] 2> 2601521 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[12]} 0 8
[junit4:junit4] 2> 2601523 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[13 (1437192247808360448)]} 0 0
[junit4:junit4] 2> 2601530 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437192247811506176)]} 0 1
[junit4:junit4] 2> 2601531 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[13 (1437192247811506176)]} 0 5
[junit4:junit4] 2> 2601535 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[14 (1437192247820943360)]} 0 0
[junit4:junit4] 2> 2601541 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437192247826186240)]} 0 0
[junit4:junit4] 2> 2601543 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1437192247826186240)]} 0 3
[junit4:junit4] 2> 2601543 T6790 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[14]} 0 5
[junit4:junit4] 2> 2601546 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[15 (1437192247832477696)]} 0 0
[junit4:junit4] 2> 2601557 T6803 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437192247839817728)]} 0 0
[junit4:junit4] 2> 2601558 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1437192247839817728)]} 0 5
[junit4:junit4] 2> 2601558 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[15]} 0 7
[junit4:junit4] 2> 2601561 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[16 (1437192247848206336)]} 0 0
[junit4:junit4] 2> 2601569 T6804 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437192247852400640)]} 0 0
[junit4:junit4] 2> 2601570 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[16 (1437192247852400640)]} 0 5
[junit4:junit4] 2> 2601573 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[17 (1437192247860789248)]} 0 0
[junit4:junit4] 2> 2601580 T6820 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437192247864983552)]} 0 0
[junit4:junit4] 2> 2601581 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[17 (1437192247864983552)]} 0 4
[junit4:junit4] 2> 2601586 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[18 (1437192247873372160)]} 0 1
[junit4:junit4] 2> 2601594 T6821 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437192247880712192)]} 0 0
[junit4:junit4] 2> 2601595 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1437192247880712192)]} 0 3
[junit4:junit4] 2> 2601596 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[18]} 0 7
[junit4:junit4] 2> 2601599 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[19 (1437192247888052224)]} 0 0
[junit4:junit4] 2> 2601610 T6822 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437192247895392256)]} 0 1
[junit4:junit4] 2> 2601611 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1437192247895392256)]} 0 5
[junit4:junit4] 2> 2601613 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[19]} 0 10
[junit4:junit4] 2> 2601617 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[20 (1437192247906926592)]} 0 0
[junit4:junit4] 2> 2601625 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437192247912169472)]} 0 1
[junit4:junit4] 2> 2601626 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[20 (1437192247912169472)]} 0 4
[junit4:junit4] 2> 2601629 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[21 (1437192247919509504)]} 0 0
[junit4:junit4] 2> 2601640 T6823 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437192247927898112)]} 0 0
[junit4:junit4] 2> 2601642 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[21 (1437192247927898112)]} 0 5
[junit4:junit4] 2> 2601642 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[21]} 0 8
[junit4:junit4] 2> 2601645 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[22 (1437192247936286720)]} 0 0
[junit4:junit4] 2> 2601653 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437192247941529600)]} 0 0
[junit4:junit4] 2> 2601654 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[22 (1437192247941529600)]} 0 4
[junit4:junit4] 2> 2601657 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[23 (1437192247948869632)]} 0 0
[junit4:junit4] 2> 2601664 T6824 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437192247952015360)]} 0 0
[junit4:junit4] 2> 2601665 T6790 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[23 (1437192247952015360)]} 0 5
[junit4:junit4] 2> 2601667 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[24 (1437192247959355392)]} 0 0
[junit4:junit4] 2> 2601673 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437192247962501120)]} 0 0
[junit4:junit4] 2> 2601675 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[24 (1437192247962501120)]} 0 5
[junit4:junit4] 2> 2601678 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[25 (1437192247970889728)]} 0 0
[junit4:junit4] 2> 2601683 T6819 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437192247974035456)]} 0 0
[junit4:junit4] 2> 2601684 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[25 (1437192247974035456)]} 0 3
[junit4:junit4] 2> 2601687 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[26 (1437192247980326912)]} 0 0
[junit4:junit4] 2> 2601693 T6820 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437192247983472640)]} 0 0
[junit4:junit4] 2> 2601694 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[26 (1437192247983472640)]} 0 4
[junit4:junit4] 2> 2601697 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[27 (1437192247990812672)]} 0 0
[junit4:junit4] 2> 2601705 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437192247996055552)]} 0 0
[junit4:junit4] 2> 2601706 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1437192247996055552)]} 0 4
[junit4:junit4] 2> 2601706 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[27]} 0 6
[junit4:junit4] 2> 2601711 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[28 (1437192248004444160)]} 0 1
[junit4:junit4] 2> 2601718 T6803 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437192248009687040)]} 0 0
[junit4:junit4] 2> 2601719 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1437192248009687040)]} 0 4
[junit4:junit4] 2> 2601720 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[28]} 0 7
[junit4:junit4] 2> 2601723 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[29 (1437192248018075648)]} 0 0
[junit4:junit4] 2> 2601732 T6821 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437192248024367104)]} 0 0
[junit4:junit4] 2> 2601733 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1437192248024367104)]} 0 4
[junit4:junit4] 2> 2601735 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[29]} 0 8
[junit4:junit4] 2> 2601737 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[30 (1437192248032755712)]} 0 0
[junit4:junit4] 2> 2601743 T6823 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437192248035901440)]} 0 0
[junit4:junit4] 2> 2601744 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[30 (1437192248035901440)]} 0 4
[junit4:junit4] 2> 2601747 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[31 (1437192248043241472)]} 0 0
[junit4:junit4] 2> 2601753 T6824 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437192248047435776)]} 0 0
[junit4:junit4] 2> 2601755 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1437192248047435776)]} 0 4
[junit4:junit4] 2> 2601756 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[31]} 0 7
[junit4:junit4] 2> 2601759 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[32 (1437192248055824384)]} 0 0
[junit4:junit4] 2> 2601766 T6804 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437192248058970112)]} 0 1
[junit4:junit4] 2> 2601767 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[32 (1437192248058970112)]} 0 5
[junit4:junit4] 2> 2601769 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[33 (1437192248066310144)]} 0 0
[junit4:junit4] 2> 2601776 T6819 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437192248070504448)]} 0 0
[junit4:junit4] 2> 2601777 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[33 (1437192248070504448)]} 0 4
[junit4:junit4] 2> 2601780 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[34 (1437192248077844480)]} 0 0
[junit4:junit4] 2> 2601788 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437192248082038784)]} 0 1
[junit4:junit4] 2> 2601789 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[34 (1437192248082038784)]} 0 5
[junit4:junit4] 2> 2601790 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[35 (1437192248088330240)]} 0 0
[junit4:junit4] 2> 2601796 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437192248091475968)]} 0 0
[junit4:junit4] 2> 2601797 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[35 (1437192248091475968)]} 0 4
[junit4:junit4] 2> 2601800 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[36 (1437192248098816000)]} 0 0
[junit4:junit4] 2> 2601805 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437192248101961728)]} 0 0
[junit4:junit4] 2> 2601806 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[36 (1437192248101961728)]} 0 3
[junit4:junit4] 2> 2601809 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[37 (1437192248108253184)]} 0 0
[junit4:junit4] 2> 2601816 T6820 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437192248113496064)]} 0 0
[junit4:junit4] 2> 2601817 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[37 (1437192248113496064)]} 0 3
[junit4:junit4] 2> 2601818 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[37]} 0 6
[junit4:junit4] 2> 2601822 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[38 (1437192248121884672)]} 0 0
[junit4:junit4] 2> 2601830 T6803 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437192248128176128)]} 0 0
[junit4:junit4] 2> 2601831 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1437192248128176128)]} 0 3
[junit4:junit4] 2> 2601831 T6790 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[38]} 0 5
[junit4:junit4] 2> 2601834 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[39 (1437192248134467584)]} 0 0
[junit4:junit4] 2> 2601841 T6822 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437192248139710464)]} 0 0
[junit4:junit4] 2> 2601843 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1437192248139710464)]} 0 4
[junit4:junit4] 2> 2601844 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[39]} 0 7
[junit4:junit4] 2> 2601847 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[40 (1437192248148099072)]} 0 0
[junit4:junit4] 2> 2601854 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437192248153341952)]} 0 0
[junit4:junit4] 2> 2601855 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1437192248153341952)]} 0 3
[junit4:junit4] 2> 2601856 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[40]} 0 6
[junit4:junit4] 2> 2601859 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[41 (1437192248160681984)]} 0 0
[junit4:junit4] 2> 2601867 T6804 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437192248166973440)]} 0 0
[junit4:junit4] 2> 2601868 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1437192248166973440)]} 0 3
[junit4:junit4] 2> 2601869 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[41]} 0 6
[junit4:junit4] 2> 2601872 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[42 (1437192248174313472)]} 0 0
[junit4:junit4] 2> 2601876 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437192248176410624)]} 0 0
[junit4:junit4] 2> 2601877 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[42 (1437192248176410624)]} 0 3
[junit4:junit4] 2> 2601881 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[43 (1437192248183750656)]} 0 0
[junit4:junit4] 2> 2601888 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437192248186896384)]} 0 0
[junit4:junit4] 2> 2601889 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[43 (1437192248186896384)]} 0 5
[junit4:junit4] 2> 2601893 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[44 (1437192248196333568)]} 0 0
[junit4:junit4] 2> 2601899 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437192248199479296)]} 0 0
[junit4:junit4] 2> 2601900 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[44 (1437192248199479296)]} 0 4
[junit4:junit4] 2> 2601903 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[45 (1437192248206819328)]} 0 0
[junit4:junit4] 2> 2601909 T6821 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437192248209965056)]} 0 0
[junit4:junit4] 2> 2601910 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[45 (1437192248209965056)]} 0 4
[junit4:junit4] 2> 2601913 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[46 (1437192248217305088)]} 0 0
[junit4:junit4] 2> 2601920 T6803 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1437192248221499392)]} 0 0
[junit4:junit4] 2> 2601921 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1437192248221499392)]} 0 4
[junit4:junit4] 2> 2601922 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[46]} 0 7
[junit4:junit4] 2> 2601925 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[47 (1437192248229888000)]} 0 0
[junit4:junit4] 2> 2601932 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1437192248235130880)]} 0 0
[junit4:junit4] 2> 2601933 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1437192248235130880)]} 0 3
[junit4:junit4] 2> 2601934 T6790 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[47]} 0 6
[junit4:junit4] 2> 2601937 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[48 (1437192248242470912)]} 0 0
[junit4:junit4] 2> 2601944 T6804 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1437192248247713792)]} 0 0
[junit4:junit4] 2> 2601945 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1437192248247713792)]} 0 3
[junit4:junit4] 2> 2601946 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[48]} 0 6
[junit4:junit4] 2> 2601950 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[49 (1437192248256102400)]} 0 1
[junit4:junit4] 2> 2601958 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1437192248262393856)]} 0 0
[junit4:junit4] 2> 2601960 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1437192248262393856)]} 0 4
[junit4:junit4] 2> 2601961 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[49]} 0 7
[junit4:junit4] 2> 2601963 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[50 (1437192248269733888)]} 0 0
[junit4:junit4] 2> 2601969 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1437192248272879616)]} 0 0
[junit4:junit4] 2> 2601970 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[50 (1437192248272879616)]} 0 4
[junit4:junit4] 2> 2601973 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[51 (1437192248280219648)]} 0 0
[junit4:junit4] 2> 2601982 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1437192248287559680)]} 0 0
[junit4:junit4] 2> 2601983 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[51 (1437192248287559680)]} 0 3
[junit4:junit4] 2> 2601984 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[51]} 0 7
[junit4:junit4] 2> 2601987 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[52 (1437192248294899712)]} 0 0
[junit4:junit4] 2> 2601995 T6803 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1437192248300142592)]} 0 0
[junit4:junit4] 2> 2601996 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[52 (1437192248300142592)]} 0 4
[junit4:junit4] 2> 2601998 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[52]} 0 8
[junit4:junit4] 2> 2601999 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[53 (1437192248307482624)]} 0 0
[junit4:junit4] 2> 2602008 T6823 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1437192248312725504)]} 0 0
[junit4:junit4] 2> 2602009 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1437192248312725504)]} 0 5
[junit4:junit4] 2> 2602010 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[53]} 0 8
[junit4:junit4] 2> 2602012 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[54 (1437192248321114112)]} 0 0
[junit4:junit4] 2> 2602021 T6806 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1437192248326356992)]} 0 0
[junit4:junit4] 2> 2602023 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1437192248326356992)]} 0 6
[junit4:junit4] 2> 2602025 T6790 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[54]} 0 10
[junit4:junit4] 2> 2602028 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[55 (1437192248337891328)]} 0 0
[junit4:junit4] 2> 2602034 T6804 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1437192248341037056)]} 0 0
[junit4:junit4] 2> 2602036 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[55 (1437192248341037056)]} 0 5
[junit4:junit4] 2> 2602038 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[56 (1437192248348377088)]} 0 0
[junit4:junit4] 2> 2602052 T6824 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1437192248354668544)]} 0 1
[junit4:junit4] 2> 2602053 T6789 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1437192248354668544)]} 0 9
[junit4:junit4] 2> 2602054 T6773 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[56]} 0 13
[junit4:junit4] 2> 2602056 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[57 (1437192248367251456)]} 0 0
[junit4:junit4] 2> 2602063 T6819 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1437192248371445760)]} 0 0
[junit4:junit4] 2> 2602064 T6788 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[57 (1437192248371445760)]} 0 4
[junit4:junit4] 2> 2602067 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[58 (1437192248378785792)]} 0 0
[junit4:junit4] 2> 2602075 T6820 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1437192248384028672)]} 0 0
[junit4:junit4] 2> 2602076 T6787 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[58 (1437192248384028672)]} 0 4
[junit4:junit4] 2> 2602077 T6771 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[58]} 0 7
[junit4:junit4] 2> 2602079 T6750 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[59 (1437192248391368704)]} 0 0
[junit4:junit4] 2> 2602084 T6805 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1437192248394514432)]} 0 0
[junit4:junit4] 2> 2602085 T6775 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[59 (1437192248394514432)]} 0 3
[junit4:junit4] 2> 2602088 T6755 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[60 (1437192248400805888)]} 0 0
[junit4:junit4] 2> 2602093 T6822 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1437192248403951616)]} 0 0
[junit4:junit4] 2> 2602094 T6791 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[60 (1437192248403951616)]} 0 3
[junit4:junit4] 2> 2602098 T6751 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[61 (1437192248411291648)]} 0 1
[junit4:junit4] 2> 2602107 T6807 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1437192248416534528)]} 0 1
[junit4:junit4] 2> 2602109 T6770 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[61 (1437192248416534528)]} 0 7
[junit4:junit4] 2> 2602113 T6752 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[62 (1437192248427020288)]} 0 1
[junit4:junit4] 2> 2602123 T6821 C10962 P51836 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51817/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1437192248435408896)]} 0 0
[junit4:junit4] 2> 2602124 T6786 C10963 P51817 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[62 (1437192248435408896)]} 0 4
[junit4:junit4] 2> 2602126 T6772 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[62]} 0 9
[junit4:junit4] 2> 2602129 T6754 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[63 (1437192248443797504)]} 0 0
[junit4:junit4] 2> 2602138 T6802 C10960 P51826 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={distrib.from=http://127.0.0.1:51808/arh/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1437192248450088960)]} 0 1
[junit4:junit4] 2> 2602140 T6774 C10961 P51808 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[63 (1437192248450088960)]} 0 6
[junit4:junit4] 2> 2602145 T6753 C10964 P51796 oasup.LogUpdateProcessor.finish [collection1] webapp=/arh path=/update params={wt=javabin&version=2} {add=[64 (1437192248459526144)]} 0 1
[junit4:junit4] 2> 2602152 T6803 C10960 P51826 oasup.LogU
[...truncated too long message...]
change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 2693098 T6828 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2694296 T6828 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2694294 T6811 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2694297 T6737 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 51796
[junit4:junit4] 2> 2694317 T6737 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2694318 T6737 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51789 51789
[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=CFFA791876980FF1 -Dtests.slow=true -Dtests.locale=ru_RU -Dtests.timezone=Asia/Yakutsk -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 121s | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:51808/arh returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([CFFA791876980FF1:4E1CF70001C76FCD]: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> 2694329 T6737 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=MockVariableIntBlock(baseBlockSize=59), _version_=Pulsing41(freqCutoff=9 minBlockSize=6 maxBlockSize=12), n_ti=Pulsing41(freqCutoff=9 minBlockSize=6 maxBlockSize=12)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=ru_RU, timezone=Asia/Yakutsk
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Oracle Corporation 1.7.0_21 (32-bit)/cpus=2,threads=3,free=211061760,total=356270080
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DocumentAnalysisRequestHandlerTest, TestArbitraryIndexDir, CoreContainerCoreInitFailuresTest, TestRandomFaceting, TestSchemaResource, BasicZkTest, TestStressReorder, TestFiltering, ShardSplitTest, DateMathParserTest, RegexBoostProcessorTest, OverseerTest, TestSolrQueryParserDefaultOperatorResource, IndexReaderFactoryTest, TestAddFieldRealTimeGet, TestBinaryField, QueryEqualityTest, SampleTest, LeaderElectionIntegrationTest, TestRangeQuery, TestNumberUtils, SystemInfoHandlerTest, TestUpdate, TestManagedSchemaFieldResource, TestDocumentBuilder, MoreLikeThisHandlerTest, TestLMDirichletSimilarityFactory, BasicFunctionalityTest, UpdateRequestProcessorFactoryTest, UUIDFieldTest, DirectSolrSpellCheckerTest, TestQueryTypes, ResponseLogComponentTest, SpatialFilterTest, TestDynamicFieldCollectionResource, UpdateParamsTest, PrimUtilsTest, TestManagedSchema, TestSolrXMLSerializer, TestSchemaNameResource, SimpleFacetsTest, TestLazyCores, TestCSVResponseWriter, DocValuesMultiTest, RequiredFieldsTest, AliasIntegrationTest, TestPerFieldSimilarity, BasicDistributedZkTest, TestRandomDVFaceting, TestUniqueKeyFieldResource, TestStressLucene, NotRequiredUniqueKeyTest, PingRequestHandlerTest, DocumentBuilderTest, ZkControllerTest, DistributedSpellCheckComponentTest, MinimalSchemaTest, SOLR749Test, ZkNodePropsTest, DefaultValueUpdateProcessorTest, TestIBSimilarityFactory, SolrIndexSplitterTest, TestReversedWildcardFilterFactory, TermVectorComponentDistributedTest, ChaosMonkeyNothingIsSafeTest, TestSuggestSpellingConverter, TestSolrQueryParser, TestCharFilters, TestSolrXml, IndexSchemaTest, SortByFunctionTest, MBeansHandlerTest, TestMultiCoreConfBootstrap, TestBinaryResponseWriter, UniqFieldsUpdateProcessorFactoryTest, LukeRequestHandlerTest, CSVRequestHandlerTest, DirectSolrConnectionTest, DateFieldTest, TestSurroundQueryParser, SuggesterTSTTest, NumericFieldsTest, TestFieldTypeResource, CurrencyFieldOpenExchangeTest, URLClassifyProcessorTest, ResourceLoaderTest, TestDFRSimilarityFactory, SimplePostToolTest, TestStressRecovery, DirectUpdateHandlerTest, SolrCmdDistributorTest, FileBasedSpellCheckerTest, SpellPossibilityIteratorTest, JsonLoaderTest, TestDistributedSearch, PathHierarchyTokenizerFactoryTest, SolrIndexConfigTest, QueryParsingTest, QueryElevationComponentTest, TestPropInject, ShardRoutingCustomTest, FastVectorHighlighterTest, JSONWriterTest, TestRecovery, EchoParamsTest, TestDefaultSimilarityFactory, TestAnalyzedSuggestions, ReturnFieldsTest, TestSolr4Spatial, HighlighterConfigTest, TestMergePolicyConfig, XmlUpdateRequestHandlerTest, DistributedTermsComponentTest, TestCSVLoader, ExternalFileFieldSortTest, LeaderElectionTest, TestTrie, TestConfig, RecoveryZkTest, TestSystemIdResolver, SolrCoreTest, ShowFileRequestHandlerTest, TestElisionMultitermQuery, SignatureUpdateProcessorFactoryTest, HardAutoCommitTest, PolyFieldTest, OverseerCollectionProcessorTest, TestQuerySenderNoQuery, RequestHandlersTest, BadIndexSchemaTest, AlternateDirectoryTest, CurrencyFieldXmlFileTest, TermVectorComponentTest, AnalysisAfterCoreReloadTest, TestReloadAndDeleteDocs, SuggesterFSTTest, SolrTestCaseJ4Test, DisMaxRequestHandlerTest, TestCoreContainer, CoreAdminHandlerTest, UnloadDistributedZkTest, IndexBasedSpellCheckerTest, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test, CollectionsAPIDistributedZkTest, SyncSliceTest, OpenCloseCoreStressTest, ShardRoutingTest, FullSolrCloudDistribCmdsTest, TestReplicationHandler, ClusterStateUpdateTest, ZkSolrClientTest, TestZkChroot, ZkCLITest, SliceStateUpdateTest, AutoCommitTest, TestDistributedGrouping, TestFaceting, TestHashPartitioner, TestRealTimeGet, TestJoin, TestReload, TestStressVersions, StatsComponentTest, SpellCheckComponentTest, TestGroupingSearch, PeerSyncTest, ConvertedLegacyTest, TestSort, TestFunctionQuery, TestBadConfig, TestIndexSearcher, HighlighterTest, SoftAutoCommitTest, DistributedQueryElevationComponentTest, TestCoreDiscovery, TestExtendedDismaxParser, SpellCheckCollatorTest, SolrRequestParserTest, TestFoldingMultitermQuery, DocValuesTest, SuggesterTest, SuggesterWFSTTest, NoCacheHeaderTest, WordBreakSolrSpellCheckerTest, SchemaVersionSpecificBehaviorTest, SolrCoreCheckLockOnStartupTest, TestPseudoReturnFields, FieldMutatingUpdateProcessorTest, TestAtomicUpdateErrorCases, TestWordDelimiterFilterFactory, DirectUpdateHandlerOptimizeTest, StatelessScriptUpdateProcessorFactoryTest, TestRemoteStreaming, DistanceFunctionTest, TestSolrDeletionPolicy1, SolrInfoMBeanTest, XsltUpdateRequestHandlerTest, DebugComponentTest, CacheHeaderTest, TestQueryUtils, StandardRequestHandlerTest, TestWriterPerf, PrimitiveFieldTypeTest, TestOmitPositions, TermsComponentTest, TestValueSourceCache, TestIndexingPerformance, FieldAnalysisRequestHandlerTest, IndexSchemaRuntimeFieldTest, LoggingHandlerTest, SolrPluginUtilsTest, TestJmxIntegration, TestCollationField, BinaryUpdateRequestHandlerTest, TestPartialUpdateDeduplication, TestPHPSerializedResponseWriter, TestComponentsName, SearchHandlerTest, TestLFUCache, TestQuerySenderListener, TestPropInjectDefaults, TestSolrIndexConfig, CopyFieldTest, BadComponentTest, TestSolrDeletionPolicy2, MultiTermTest, TestDocSet, TestSearchPerf, OutputWriterTest, TestFuzzyAnalyzedSuggestions, TestSolrCoreProperties, TestPostingsSolrHighlighter, TestLuceneMatchVersion, TestPhraseSuggestions, TestCodecSupport, SynonymTokenizerTest, TestXIncludeConfig, TestSweetSpotSimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestBM25SimilarityFactory, TestFastWriter, LegacyHTMLStripCharFilterTest, TestJmxMonitoredMap, TestPluginEnable, TimeZoneUtilsTest, TestFastOutputStream, ScriptEngineTest, OpenExchangeRatesOrgProviderTest, PluginInfoTest, TestFastLRUCache, PreAnalyzedFieldTest, SpellingQueryConverterTest, DOMUtilTest, RAMDirectoryFactoryTest, ClusterStateTest, TestSolrJ, TestLRUCache, TestUtils, SliceStateTest, FileUtilsTest, CircularListTest, TestRTGBase, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed in 121.49s, 1 test, 1 error <<< FAILURES!
[...truncated 66 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:385: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:365: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1240: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:884: There were test failures: 296 suites, 1243 tests, 1 error, 18 ignored (12 assumptions)
Total time: 69 minutes 6 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure