You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/26 01:10:08 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4017 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4017/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:63494 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:63494 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([40EB31A9E3F5D5DF:C10DBFB194AAB5E3]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9651 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1583761 T2876 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1583767 T2876 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1369522780135
[junit4:junit4] 2> 1583769 T2876 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1583769 T2877 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1583870 T2876 oasc.ZkTestServer.run start zk server on port:63487
[junit4:junit4] 2> 1583871 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1583875 T2883 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f751d72 name:ZooKeeperConnection Watcher:127.0.0.1:63487 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1583875 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1583876 T2876 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1583890 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1583892 T2885 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2360580f name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1583892 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1583893 T2876 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1583902 T2876 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1583904 T2876 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1583913 T2876 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1583916 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1583917 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1583927 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1583928 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1584032 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1584033 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1584042 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1584043 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1584045 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1584046 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1584049 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1584050 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1584052 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1584053 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1584061 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1584062 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1584065 T2876 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1584065 T2876 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1584341 T2876 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1584345 T2876 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63490
[junit4:junit4] 2> 1584346 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1584347 T2876 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1584347 T2876 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442
[junit4:junit4] 2> 1584348 T2876 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/solr.xml
[junit4:junit4] 2> 1584348 T2876 oasc.CoreContainer.<init> New CoreContainer 1928964781
[junit4:junit4] 2> 1584349 T2876 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/'
[junit4:junit4] 2> 1584350 T2876 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/'
[junit4:junit4] 2> 1584500 T2876 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1584501 T2876 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1584502 T2876 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1584503 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1584503 T2876 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1584504 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1584504 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1584505 T2876 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1584505 T2876 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1584506 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1584524 T2876 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1584525 T2876 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63487/solr
[junit4:junit4] 2> 1584525 T2876 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1584526 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1584530 T2896 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f569b71 name:ZooKeeperConnection Watcher:127.0.0.1:63487 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1584530 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1584533 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1584544 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1584546 T2898 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@107212d8 name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1584546 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1584548 T2876 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1584559 T2876 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1584562 T2876 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1584569 T2876 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63490_
[junit4:junit4] 2> 1584570 T2876 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63490_
[junit4:junit4] 2> 1584577 T2876 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1584590 T2876 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1584597 T2876 oasc.Overseer.start Overseer (id=89753044919386115-127.0.0.1:63490_-n_0000000000) starting
[junit4:junit4] 2> 1584601 T2876 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1584633 T2900 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1584633 T2876 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1584644 T2876 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1584646 T2876 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1584648 T2899 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1584652 T2901 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/collection1
[junit4:junit4] 2> 1584652 T2901 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1584653 T2901 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1584653 T2901 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1584654 T2901 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/collection1/'
[junit4:junit4] 2> 1584656 T2901 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1584657 T2901 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/collection1/lib/README' to classloader
[junit4:junit4] 2> 1584715 T2901 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1584779 T2901 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1584881 T2901 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1584887 T2901 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1585487 T2901 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1585490 T2901 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1585491 T2901 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1585495 T2901 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1585514 T2901 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1585514 T2901 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369522780442/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/control/data/
[junit4:junit4] 2> 1585515 T2901 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7dee05dc
[junit4:junit4] 2> 1585515 T2901 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1585516 T2901 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/control/data
[junit4:junit4] 2> 1585516 T2901 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/control/data/index/
[junit4:junit4] 2> 1585516 T2901 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1585516 T2901 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/control/data/index
[junit4:junit4] 2> 1585520 T2901 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5c75460f lockFactory=org.apache.lucene.store.NativeFSLockFactory@251017c7)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1585520 T2901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1585522 T2901 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1585522 T2901 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1585523 T2901 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1585523 T2901 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1585524 T2901 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1585524 T2901 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1585524 T2901 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1585525 T2901 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1585525 T2901 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1585536 T2901 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1585542 T2901 oass.SolrIndexSearcher.<init> Opening Searcher@21f55f5e main
[junit4:junit4] 2> 1585542 T2901 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/control/data/tlog
[junit4:junit4] 2> 1585543 T2901 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1585543 T2901 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1585546 T2902 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@21f55f5e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1585546 T2901 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1585547 T2901 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1586152 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1586153 T2899 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:63490_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63490"}
[junit4:junit4] 2> 1586153 T2899 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1586154 T2899 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1586169 T2898 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> 1586549 T2901 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1586549 T2901 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63490 collection:control_collection shard:shard1
[junit4:junit4] 2> 1586551 T2901 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1586671 T2901 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1586699 T2901 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1586700 T2901 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1586700 T2901 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63490/collection1/
[junit4:junit4] 2> 1586700 T2901 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1586700 T2901 oasc.SyncStrategy.syncToMe http://127.0.0.1:63490/collection1/ has no replicas
[junit4:junit4] 2> 1586700 T2901 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63490/collection1/
[junit4:junit4] 2> 1586701 T2901 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1587672 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1587705 T2898 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> 1587768 T2901 oasc.ZkController.register We are http://127.0.0.1:63490/collection1/ and leader is http://127.0.0.1:63490/collection1/
[junit4:junit4] 2> 1587768 T2901 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63490
[junit4:junit4] 2> 1587768 T2901 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1587769 T2901 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1587769 T2901 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1587771 T2901 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1587772 T2876 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1587773 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1587773 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1587784 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1587785 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1587787 T2905 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18082755 name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1587788 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1587789 T2876 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1587791 T2876 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1588088 T2876 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1588092 T2876 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63494
[junit4:junit4] 2> 1588092 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1588093 T2876 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1588094 T2876 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158
[junit4:junit4] 2> 1588094 T2876 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/solr.xml
[junit4:junit4] 2> 1588095 T2876 oasc.CoreContainer.<init> New CoreContainer 1846337251
[junit4:junit4] 2> 1588095 T2876 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/'
[junit4:junit4] 2> 1588096 T2876 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/'
[junit4:junit4] 2> 1588231 T2876 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1588231 T2876 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1588232 T2876 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1588232 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1588233 T2876 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1588233 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1588234 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1588234 T2876 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1588235 T2876 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1588236 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1588253 T2876 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1588254 T2876 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63487/solr
[junit4:junit4] 2> 1588254 T2876 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1588255 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1588258 T2916 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@73f2ac96 name:ZooKeeperConnection Watcher:127.0.0.1:63487 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1588259 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1588275 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1588285 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1588288 T2918 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25eae711 name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1588288 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1588299 T2876 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1589221 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1589222 T2899 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:63490_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63490"}
[junit4:junit4] 2> 1589236 T2905 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> 1589236 T2898 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> 1589236 T2918 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> 1589302 T2876 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63494_
[junit4:junit4] 2> 1589304 T2876 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63494_
[junit4:junit4] 2> 1589306 T2918 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1589306 T2905 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1589306 T2898 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1589308 T2918 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1589308 T2905 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1589316 T2898 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1589322 T2919 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/collection1
[junit4:junit4] 2> 1589322 T2919 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1589323 T2919 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1589323 T2919 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1589325 T2919 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/collection1/'
[junit4:junit4] 2> 1589326 T2919 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1589327 T2919 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/collection1/lib/README' to classloader
[junit4:junit4] 2> 1589384 T2919 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1589449 T2919 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1589550 T2919 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1589557 T2919 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1590073 T2919 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1590078 T2919 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1590080 T2919 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1590085 T2919 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1590106 T2919 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1590107 T2919 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369522784158/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty1/
[junit4:junit4] 2> 1590107 T2919 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7dee05dc
[junit4:junit4] 2> 1590107 T2919 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1590108 T2919 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty1
[junit4:junit4] 2> 1590108 T2919 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty1/index/
[junit4:junit4] 2> 1590109 T2919 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1590110 T2919 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty1/index
[junit4:junit4] 2> 1590113 T2919 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1110bbb1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4db60ec5)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1590114 T2919 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1590117 T2919 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1590117 T2919 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1590118 T2919 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1590119 T2919 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1590119 T2919 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1590120 T2919 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1590120 T2919 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1590121 T2919 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1590121 T2919 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1590138 T2919 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1590145 T2919 oass.SolrIndexSearcher.<init> Opening Searcher@4551326 main
[junit4:junit4] 2> 1590146 T2919 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty1/tlog
[junit4:junit4] 2> 1590147 T2919 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1590147 T2919 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1590151 T2920 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4551326 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1590153 T2919 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1590154 T2919 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1590740 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1590741 T2899 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:63494_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63494"}
[junit4:junit4] 2> 1590741 T2899 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1590742 T2899 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1590757 T2918 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> 1590757 T2898 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> 1590757 T2905 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> 1591156 T2919 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1591156 T2919 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63494 collection:collection1 shard:shard1
[junit4:junit4] 2> 1591157 T2919 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1591176 T2919 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1591188 T2919 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1591188 T2919 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1591188 T2919 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63494/collection1/
[junit4:junit4] 2> 1591188 T2919 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1591188 T2919 oasc.SyncStrategy.syncToMe http://127.0.0.1:63494/collection1/ has no replicas
[junit4:junit4] 2> 1591189 T2919 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63494/collection1/
[junit4:junit4] 2> 1591189 T2919 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1592262 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1592282 T2898 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> 1592282 T2905 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> 1592282 T2918 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> 1592325 T2919 oasc.ZkController.register We are http://127.0.0.1:63494/collection1/ and leader is http://127.0.0.1:63494/collection1/
[junit4:junit4] 2> 1592325 T2919 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63494
[junit4:junit4] 2> 1592325 T2919 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1592325 T2919 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1592326 T2919 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1592327 T2919 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1592328 T2876 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1592329 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1592330 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1592626 T2876 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1592629 T2876 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63497
[junit4:junit4] 2> 1592630 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1592631 T2876 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1592631 T2876 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713
[junit4:junit4] 2> 1592632 T2876 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/solr.xml
[junit4:junit4] 2> 1592632 T2876 oasc.CoreContainer.<init> New CoreContainer 257980270
[junit4:junit4] 2> 1592633 T2876 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/'
[junit4:junit4] 2> 1592634 T2876 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/'
[junit4:junit4] 2> 1592791 T2876 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1592792 T2876 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1592792 T2876 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1592793 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1592793 T2876 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1592794 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1592794 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1592795 T2876 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1592795 T2876 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1592796 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1592814 T2876 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1592814 T2876 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63487/solr
[junit4:junit4] 2> 1592815 T2876 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1592816 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1592819 T2932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@462d51e3 name:ZooKeeperConnection Watcher:127.0.0.1:63487 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1592820 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1592831 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1592842 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1592845 T2934 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2af32394 name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1592845 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1592854 T2876 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1593793 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1593794 T2899 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:63494_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63494"}
[junit4:junit4] 2> 1593816 T2934 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> 1593816 T2898 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> 1593816 T2905 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> 1593816 T2918 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> 1593857 T2876 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63497_
[junit4:junit4] 2> 1593859 T2876 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63497_
[junit4:junit4] 2> 1593861 T2918 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> 1593861 T2898 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> 1593861 T2905 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> 1593861 T2934 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1593862 T2934 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> 1593862 T2918 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1593870 T2898 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1593870 T2905 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1593874 T2935 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/collection1
[junit4:junit4] 2> 1593875 T2935 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1593875 T2935 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1593875 T2935 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1593876 T2935 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/collection1/'
[junit4:junit4] 2> 1593878 T2935 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1593878 T2935 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/collection1/lib/README' to classloader
[junit4:junit4] 2> 1593916 T2935 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1593961 T2935 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1594062 T2935 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1594066 T2935 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1594476 T2935 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1594479 T2935 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1594481 T2935 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1594485 T2935 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1594503 T2935 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1594504 T2935 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369522788713/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty2/
[junit4:junit4] 2> 1594504 T2935 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7dee05dc
[junit4:junit4] 2> 1594504 T2935 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1594505 T2935 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty2
[junit4:junit4] 2> 1594505 T2935 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty2/index/
[junit4:junit4] 2> 1594506 T2935 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1594506 T2935 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty2/index
[junit4:junit4] 2> 1594509 T2935 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f32a52f lockFactory=org.apache.lucene.store.NativeFSLockFactory@612c4ede)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1594509 T2935 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1594511 T2935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1594512 T2935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1594512 T2935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1594513 T2935 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1594513 T2935 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1594513 T2935 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1594514 T2935 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1594514 T2935 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1594514 T2935 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1594526 T2935 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1594531 T2935 oass.SolrIndexSearcher.<init> Opening Searcher@8f23bf8 main
[junit4:junit4] 2> 1594531 T2935 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty2/tlog
[junit4:junit4] 2> 1594532 T2935 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1594533 T2935 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1594536 T2936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8f23bf8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1594538 T2935 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1594538 T2935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1595320 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1595321 T2899 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:63497_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63497"}
[junit4:junit4] 2> 1595321 T2899 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1595322 T2899 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1595335 T2898 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> 1595335 T2905 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> 1595335 T2934 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> 1595335 T2918 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> 1595541 T2935 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1595541 T2935 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63497 collection:collection1 shard:shard2
[junit4:junit4] 2> 1595542 T2935 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1595559 T2935 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1595571 T2935 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1595571 T2935 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1595572 T2935 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63497/collection1/
[junit4:junit4] 2> 1595572 T2935 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1595572 T2935 oasc.SyncStrategy.syncToMe http://127.0.0.1:63497/collection1/ has no replicas
[junit4:junit4] 2> 1595572 T2935 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63497/collection1/
[junit4:junit4] 2> 1595573 T2935 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1596839 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1596868 T2898 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> 1596868 T2934 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> 1596868 T2905 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> 1596868 T2918 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> 1596912 T2935 oasc.ZkController.register We are http://127.0.0.1:63497/collection1/ and leader is http://127.0.0.1:63497/collection1/
[junit4:junit4] 2> 1596912 T2935 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63497
[junit4:junit4] 2> 1596912 T2935 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1596912 T2935 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1596913 T2935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1596919 T2935 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1596920 T2876 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1596921 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1596921 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1597162 T2876 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1597165 T2876 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:44996
[junit4:junit4] 2> 1597165 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1597166 T2876 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1597166 T2876 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302
[junit4:junit4] 2> 1597167 T2876 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/solr.xml
[junit4:junit4] 2> 1597167 T2876 oasc.CoreContainer.<init> New CoreContainer 202701023
[junit4:junit4] 2> 1597168 T2876 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/'
[junit4:junit4] 2> 1597168 T2876 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/'
[junit4:junit4] 2> 1597277 T2876 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1597278 T2876 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1597278 T2876 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1597279 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1597279 T2876 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1597280 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1597280 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1597280 T2876 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1597281 T2876 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1597281 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1597295 T2876 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1597296 T2876 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63487/solr
[junit4:junit4] 2> 1597296 T2876 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1597297 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1597325 T2948 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28afc1c8 name:ZooKeeperConnection Watcher:127.0.0.1:63487 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1597326 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1597339 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1597349 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1597351 T2950 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23445a5 name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1597351 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1597361 T2876 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1598365 T2876 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44996_
[junit4:junit4] 2> 1598367 T2876 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44996_
[junit4:junit4] 2> 1598370 T2898 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> 1598370 T2905 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> 1598370 T2918 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> 1598370 T2934 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1598370 T2950 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1598371 T2934 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> 1598381 T2898 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1598381 T2905 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1598382 T2918 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1598382 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1598383 T2899 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:63497_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63497"}
[junit4:junit4] 2> 1598386 T2951 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/collection1
[junit4:junit4] 2> 1598386 T2951 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1598395 T2950 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> 1598395 T2918 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> 1598395 T2905 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> 1598395 T2951 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1598395 T2898 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> 1598395 T2934 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> 1598396 T2951 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1598398 T2951 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/collection1/'
[junit4:junit4] 2> 1598399 T2951 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1598400 T2951 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/collection1/lib/README' to classloader
[junit4:junit4] 2> 1598455 T2951 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1598524 T2951 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1598626 T2951 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1598631 T2951 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1599098 T2951 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1599101 T2951 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1599103 T2951 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1599108 T2951 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1599142 T2951 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1599142 T2951 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369522793302/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/
[junit4:junit4] 2> 1599143 T2951 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7dee05dc
[junit4:junit4] 2> 1599143 T2951 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1599144 T2951 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3
[junit4:junit4] 2> 1599144 T2951 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index/
[junit4:junit4] 2> 1599144 T2951 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1599145 T2951 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index
[junit4:junit4] 2> 1599148 T2951 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@17ae5e4c lockFactory=org.apache.lucene.store.NativeFSLockFactory@3461c06a)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1599148 T2951 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1599151 T2951 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1599151 T2951 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1599152 T2951 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1599152 T2951 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1599153 T2951 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1599153 T2951 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1599153 T2951 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1599154 T2951 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1599154 T2951 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1599166 T2951 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1599173 T2951 oass.SolrIndexSearcher.<init> Opening Searcher@2dd7d5d6 main
[junit4:junit4] 2> 1599173 T2951 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/tlog
[junit4:junit4] 2> 1599174 T2951 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1599174 T2951 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1599177 T2952 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2dd7d5d6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1599179 T2951 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1599179 T2951 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1599899 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1599900 T2899 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:44996_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44996"}
[junit4:junit4] 2> 1599900 T2899 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1599901 T2899 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1599913 T2950 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> 1599913 T2918 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> 1599913 T2934 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> 1599913 T2898 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> 1599913 T2905 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> 1600182 T2951 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1600182 T2951 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44996 collection:collection1 shard:shard1
[junit4:junit4] 2> 1600185 T2951 oasc.ZkController.register We are http://127.0.0.1:44996/collection1/ and leader is http://127.0.0.1:63494/collection1/
[junit4:junit4] 2> 1600186 T2951 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44996
[junit4:junit4] 2> 1600186 T2951 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1600186 T2951 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C782 name=collection1 org.apache.solr.core.SolrCore@10c70cdc url=http://127.0.0.1:44996/collection1 node=127.0.0.1:44996_ C782_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:44996_, base_url=http://127.0.0.1:44996}
[junit4:junit4] 2> 1600187 T2953 C782 P44996 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1600187 T2951 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1600188 T2953 C782 P44996 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1600188 T2953 C782 P44996 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1600188 T2953 C782 P44996 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1600189 T2876 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1600189 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1600190 T2953 C782 P44996 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1600190 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1600211 T2908 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1600410 T2876 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1600413 T2876 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:52286
[junit4:junit4] 2> 1600413 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1600414 T2876 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1600414 T2876 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576
[junit4:junit4] 2> 1600415 T2876 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/solr.xml
[junit4:junit4] 2> 1600415 T2876 oasc.CoreContainer.<init> New CoreContainer 1370970310
[junit4:junit4] 2> 1600416 T2876 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/'
[junit4:junit4] 2> 1600416 T2876 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/'
[junit4:junit4] 2> 1600515 T2876 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1600516 T2876 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1600516 T2876 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1600516 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1600517 T2876 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1600517 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1600518 T2876 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1600518 T2876 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1600518 T2876 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1600519 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1600532 T2876 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1600533 T2876 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63487/solr
[junit4:junit4] 2> 1600533 T2876 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1600534 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1600537 T2965 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e605d87 name:ZooKeeperConnection Watcher:127.0.0.1:63487 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1600538 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1600553 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1600566 T2876 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1600568 T2967 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f6869f5 name:ZooKeeperConnection Watcher:127.0.0.1:63487/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1600569 T2876 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1600577 T2876 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1601417 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1601418 T2899 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:44996_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44996"}
[junit4:junit4] 2> 1601432 T2934 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> 1601432 T2967 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> 1601432 T2905 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> 1601432 T2918 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> 1601432 T2898 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> 1601432 T2950 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> 1601581 T2876 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52286_
[junit4:junit4] 2> 1601610 T2876 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52286_
[junit4:junit4] 2> 1601634 T2898 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> 1601634 T2905 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> 1601634 T2918 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> 1601634 T2950 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> 1601634 T2967 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> 1601634 T2934 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1601635 T2898 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1601636 T2934 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> 1601637 T2905 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1601637 T2918 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1601637 T2950 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1601637 T2967 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1601641 T2968 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/collection1
[junit4:junit4] 2> 1601642 T2968 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1601642 T2968 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1601643 T2968 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1601644 T2968 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/collection1/'
[junit4:junit4] 2> 1601646 T2968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1601646 T2968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/collection1/lib/README' to classloader
[junit4:junit4] 2> 1601704 T2968 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1601769 T2968 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1601870 T2968 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1601876 T2968 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1602213 T2908 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1602213 T2908 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:44996_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1602496 T2968 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1602501 T2968 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1602503 T2968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1602508 T2968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1602528 T2968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1602528 T2968 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369522796576/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/
[junit4:junit4] 2> 1602529 T2968 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7dee05dc
[junit4:junit4] 2> 1602529 T2968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1602530 T2968 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4
[junit4:junit4] 2> 1602531 T2968 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index/
[junit4:junit4] 2> 1602531 T2968 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1602532 T2968 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index
[junit4:junit4] 2> 1602535 T2968 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@18a6c51c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b705848)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1602536 T2968 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1602539 T2968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1602539 T2968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1602540 T2968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1602541 T2968 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1602541 T2968 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1602542 T2968 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1602542 T2968 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1602543 T2968 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1602543 T2968 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1602558 T2968 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1602565 T2968 oass.SolrIndexSearcher.<init> Opening Searcher@5c1b7ca3 main
[junit4:junit4] 2> 1602565 T2968 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/tlog
[junit4:junit4] 2> 1602567 T2968 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1602567 T2968 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1602571 T2969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c1b7ca3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1602573 T2968 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1602573 T2968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1602936 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1602937 T2899 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:52286_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52286"}
[junit4:junit4] 2> 1602937 T2899 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1602937 T2899 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1602953 T2950 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> 1602953 T2905 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> 1602953 T2898 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> 1602953 T2967 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> 1602953 T2934 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> 1602953 T2918 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> 1603576 T2968 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1603576 T2968 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52286 collection:collection1 shard:shard2
[junit4:junit4] 2> 1603579 T2968 oasc.ZkController.register We are http://127.0.0.1:52286/collection1/ and leader is http://127.0.0.1:63497/collection1/
[junit4:junit4] 2> 1603579 T2968 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52286
[junit4:junit4] 2> 1603580 T2968 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1603580 T2968 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C783 name=collection1 org.apache.solr.core.SolrCore@52a00007 url=http://127.0.0.1:52286/collection1 node=127.0.0.1:52286_ C783_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52286_, base_url=http://127.0.0.1:52286}
[junit4:junit4] 2> 1603580 T2970 C783 P52286 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1603581 T2968 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1603581 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1603582 T2970 C783 P52286 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1603582 T2970 C783 P52286 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1603582 T2876 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1603583 T2876 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1603583 T2970 C783 P52286 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1603584 T2876 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1603600 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1603601 T2924 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1603602 T2876 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1603602 T2876 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1603603 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C784 name=collection1 org.apache.solr.core.SolrCore@10c70cdc url=http://127.0.0.1:44996/collection1 node=127.0.0.1:44996_ C784_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:44996_, base_url=http://127.0.0.1:44996}
[junit4:junit4] 2> 1604215 T2953 C784 P44996 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:63494/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1604215 T2953 C784 P44996 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44996 START replicas=[http://127.0.0.1:63494/collection1/] nUpdates=100
[junit4:junit4] 2> 1604215 T2953 C784 P44996 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1604216 T2953 C784 P44996 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1604217 T2953 C784 P44996 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1604217 T2953 C784 P44996 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1604217 T2953 C784 P44996 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1604217 T2953 C784 P44996 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:63494/collection1/. core=collection1
[junit4:junit4] 2> 1604217 T2953 C784 P44996 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C785 name=collection1 org.apache.solr.core.SolrCore@63c882b5 url=http://127.0.0.1:63494/collection1 node=127.0.0.1:63494_ C785_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63494_, base_url=http://127.0.0.1:63494, leader=true}
[junit4:junit4] 2> 1604223 T2909 C785 P63494 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1604226 T2910 C785 P63494 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1604229 T2910 C785 P63494 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1110bbb1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4db60ec5)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1604230 T2910 C785 P63494 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1604230 T2910 C785 P63494 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1110bbb1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4db60ec5)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1110bbb1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4db60ec5)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1604231 T2910 C785 P63494 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1604231 T2910 C785 P63494 oass.SolrIndexSearcher.<init> Opening Searcher@f4c3554 realtime
[junit4:junit4] 2> 1604232 T2910 C785 P63494 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1604232 T2910 C785 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1604233 T2953 C784 P44996 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1604233 T2953 C784 P44996 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1604235 T2911 C785 P63494 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1604235 T2911 C785 P63494 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1604236 T2953 C784 P44996 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1604236 T2953 C784 P44996 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1604236 T2953 C784 P44996 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1604238 T2911 C785 P63494 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1604238 T2953 C784 P44996 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1604239 T2953 C784 P44996 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index.20130525160000606
[junit4:junit4] 2> 1604239 T2953 C784 P44996 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@313dd36c lockFactory=org.apache.lucene.store.NativeFSLockFactory@756f896c; maxCacheMB=0.1767578125 maxMergeSizeMB=0.908203125)) fullCopy=false
[junit4:junit4] 2> 1604242 T2911 C785 P63494 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1604243 T2953 C784 P44996 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1604244 T2953 C784 P44996 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1604244 T2953 C784 P44996 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1604245 T2953 C784 P44996 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@17ae5e4c lockFactory=org.apache.lucene.store.NativeFSLockFactory@3461c06a)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@17ae5e4c lockFactory=org.apache.lucene.store.NativeFSLockFactory@3461c06a)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1604246 T2953 C784 P44996 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1604246 T2953 C784 P44996 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1604246 T2953 C784 P44996 oass.SolrIndexSearcher.<init> Opening Searcher@72c5c572 main
[junit4:junit4] 2> 1604247 T2952 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72c5c572 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1604248 T2953 C784 P44996 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index.20130525160000606 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index.20130525160000606;done=true>>]
[junit4:junit4] 2> 1604248 T2953 C784 P44996 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index.20130525160000606
[junit4:junit4] 2> 1604248 T2953 C784 P44996 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty3/index.20130525160000606
[junit4:junit4] 2> 1604249 T2953 C784 P44996 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1604249 T2953 C784 P44996 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1604249 T2953 C784 P44996 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1604249 T2953 C784 P44996 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1604251 T2953 C784 P44996 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1604457 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1604458 T2899 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:52286_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52286"}
[junit4:junit4] 2> 1604461 T2899 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:44996_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44996"}
[junit4:junit4] 2> 1604474 T2898 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> 1604474 T2905 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> 1604474 T2934 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> 1604474 T2918 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> 1604474 T2967 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> 1604474 T2950 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> 1604603 T2924 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1604603 T2924 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:52286_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 1604604 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1605606 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C783_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52286_, base_url=http://127.0.0.1:52286}
[junit4:junit4] 2> 1606605 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:63497/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1606605 T2970 C783 P52286 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52286 START replicas=[http://127.0.0.1:63497/collection1/] nUpdates=100
[junit4:junit4] 2> 1606606 T2970 C783 P52286 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1606606 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1606606 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1606606 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1606607 T2970 C783 P52286 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1606607 T2970 C783 P52286 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:63497/collection1/. core=collection1
[junit4:junit4] 2> 1606607 T2970 C783 P52286 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1606608 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C786 name=collection1 org.apache.solr.core.SolrCore@286e9f81 url=http://127.0.0.1:63497/collection1 node=127.0.0.1:63497_ C786_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63497_, base_url=http://127.0.0.1:63497, leader=true}
[junit4:junit4] 2> 1606616 T2925 C786 P63497 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1606620 T2926 C786 P63497 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1606623 T2926 C786 P63497 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f32a52f lockFactory=org.apache.lucene.store.NativeFSLockFactory@612c4ede)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1606624 T2926 C786 P63497 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1606625 T2926 C786 P63497 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f32a52f lockFactory=org.apache.lucene.store.NativeFSLockFactory@612c4ede)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f32a52f lockFactory=org.apache.lucene.store.NativeFSLockFactory@612c4ede)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1606625 T2926 C786 P63497 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1606626 T2926 C786 P63497 oass.SolrIndexSearcher.<init> Opening Searcher@47943625 realtime
[junit4:junit4] 2> 1606626 T2926 C786 P63497 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1606627 T2926 C786 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1606628 T2970 C783 P52286 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1606628 T2970 C783 P52286 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1606630 T2927 C786 P63497 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1606630 T2927 C786 P63497 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1606631 T2970 C783 P52286 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1606631 T2970 C783 P52286 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1606631 T2970 C783 P52286 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1606635 T2927 C786 P63497 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1606636 T2970 C783 P52286 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1606637 T2970 C783 P52286 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index.20130525160003003
[junit4:junit4] 2> 1606637 T2970 C783 P52286 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@b2d436d lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a008b85; maxCacheMB=0.1767578125 maxMergeSizeMB=0.908203125)) fullCopy=false
[junit4:junit4] 2> 1606640 T2927 C786 P63497 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1606642 T2970 C783 P52286 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1606643 T2970 C783 P52286 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1606643 T2970 C783 P52286 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1606645 T2970 C783 P52286 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@18a6c51c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b705848)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@18a6c51c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b705848)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1606645 T2970 C783 P52286 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1606646 T2970 C783 P52286 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1606646 T2970 C783 P52286 oass.SolrIndexSearcher.<init> Opening Searcher@62497598 main
[junit4:junit4] 2> 1606647 T2969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@62497598 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1606648 T2970 C783 P52286 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index.20130525160003003 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index.20130525160003003;done=true>>]
[junit4:junit4] 2> 1606648 T2970 C783 P52286 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index.20130525160003003
[junit4:junit4] 2> 1606649 T2970 C783 P52286 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index.20130525160003003
[junit4:junit4] 2> 1606649 T2970 C783 P52286 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1606649 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1606649 T2970 C783 P52286 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1606649 T2970 C783 P52286 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1606664 T2970 C783 P52286 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1607481 T2899 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1607482 T2899 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:52286_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52286"}
[junit4:junit4] 2> 1607500 T2898 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> 1607500 T2950 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> 1607500 T2918 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> 1607500 T2934 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> 1607500 T2905 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> 1607500 T2967 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> 1607610 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1607611 T2876 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C787 name=collection1 org.apache.solr.core.SolrCore@52371d56 url=http://127.0.0.1:63490/collection1 node=127.0.0.1:63490_ C787_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:63490_, base_url=http://127.0.0.1:63490, leader=true}
[junit4:junit4] 2> 1607618 T2888 C787 P63490 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1607621 T2888 C787 P63490 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5c75460f lockFactory=org.apache.lucene.store.NativeFSLockFactory@251017c7)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1607621 T2888 C787 P63490 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1607622 T2888 C787 P63490 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5c75460f lockFactory=org.apache.lucene.store.NativeFSLockFactory@251017c7)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5c75460f lockFactory=org.apache.lucene.store.NativeFSLockFactory@251017c7)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1607622 T2888 C787 P63490 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1607623 T2888 C787 P63490 oass.SolrIndexSearcher.<init> Opening Searcher@1bf8baaf main
[junit4:junit4] 2> 1607623 T2888 C787 P63490 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1607624 T2902 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1bf8baaf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1607625 T2888 C787 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1607633 T2928 C786 P63497 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1607635 T2928 C786 P63497 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f32a52f lockFactory=org.apache.lucene.store.NativeFSLockFactory@612c4ede)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2f32a52f lockFactory=org.apache.lucene.store.NativeFSLockFactory@612c4ede)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1607635 T2928 C786 P63497 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1607635 T2928 C786 P63497 oass.SolrIndexSearcher.<init> Opening Searcher@5ae18b3c main
[junit4:junit4] 2> 1607636 T2928 C786 P63497 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1607636 T2936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5ae18b3c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1607637 T2928 C786 P63497 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:63494/collection1/, StdNode: http://127.0.0.1:44996/collection1/, StdNode: http://127.0.0.1:52286/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1607640 T2912 C785 P63494 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1607641 T2912 C785 P63494 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1110bbb1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4db60ec5)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1110bbb1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4db60ec5)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1607642 T2912 C785 P63494 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1607642 T2912 C785 P63494 oass.SolrIndexSearcher.<init> Opening Searcher@21049bd main
[junit4:junit4] 2> 1607643 T2912 C785 P63494 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1607643 T2920 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@21049bd main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1607644 T2912 C785 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> C784_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:44996_, base_url=http://127.0.0.1:44996}
[junit4:junit4] 2> 1607648 T2940 C784 P44996 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C783_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52286_, base_url=http://127.0.0.1:52286}
[junit4:junit4] 2> 1607648 T2957 C783 P52286 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1607649 T2940 C784 P44996 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@17ae5e4c lockFactory=org.apache.lucene.store.NativeFSLockFactory@3461c06a)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@17ae5e4c lockFactory=org.apache.lucene.store.NativeFSLockFactory@3461c06a)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1607650 T2957 C783 P52286 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@18a6c51c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b705848)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@18a6c51c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b705848)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1607650 T2940 C784 P44996 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1607650 T2957 C783 P52286 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1607651 T2940 C784 P44996 oass.SolrIndexSearcher.<init> Opening Searcher@734f2e86 main
[junit4:junit4] 2> 1607652 T2957 C783 P52286 oass.SolrIndexSearcher.<init> Opening Searcher@4a4b5165 main
[junit4:junit4] 2> 1607652 T2940 C784 P44996 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1607653 T2952 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@734f2e86 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1607652 T2957 C783 P52286 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1607653 T2940 C784 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 1607653 T2969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4a4b5165 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1607654 T2957 C783 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1607655 T2928 C786 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 1607656 T2876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1607659 T2913 C785 P63494 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C788 name=collection1 org.apache.solr.core.SolrCore@10c70cdc url=http://127.0.0.1:44996/collection1 node=127.0.0.1:44996_ C788_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:44996_, base_url=http://127.0.0.1:44996}
[junit4:junit4] 2> 1607674 T2941 C788 P44996 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C789 name=collection1 org.apache.solr.core.SolrCore@286e9f81 url=http://127.0.0.1:63497/collection1 node=127.0.0.1:63497_ C789_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63497_, base_url=http://127.0.0.1:63497, leader=true}
[junit4:junit4] 2> 1607676 T2929 C789 P63497 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C790 name=collection1 org.apache.solr.core.SolrCore@52a00007 url=http://127.0.0.1:52286/collection1 node=127.0.0.1:52286_ C790_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52286_, base_url=http://127.0.0.1:52286}
[junit4:junit4] 2> 1607678 T2958 C790 P52286 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C791 name=collection1 org.apache.solr.core.SolrCore@52371d56 url=http://127.0.0.1:63490/collection1 node=127.0.0.1:63490_ C791_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:63490_, base_url=http://127.0.0.1:63490, leader=true}
[junit4:junit4] 2> 1609684 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436048745876684800)} 0 2
[junit4:junit4] 2> 1609693 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436048745881927680&update.from=http://127.0.0.1:63497/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436048745881927680)} 0 2
[junit4:junit4] 2> 1609697 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436048745885073408&update.from=http://127.0.0.1:63494/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436048745885073408)} 0 2
[junit4:junit4] 2> ASYNC NEW_CORE C792 name=collection1 org.apache.solr.core.SolrCore@63c882b5 url=http://127.0.0.1:63494/collection1 node=127.0.0.1:63494_ C792_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63494_, base_url=http://127.0.0.1:63494, leader=true}
[junit4:junit4] 2> 1609698 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436048745885073408)} 0 7
[junit4:junit4] 2> 1609699 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436048745881927680)} 0 12
[junit4:junit4] 2> 1609702 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1436048745895559168)]} 0 1
[junit4:junit4] 2> 1609711 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436048745901850624)]} 0 1
[junit4:junit4] 2> 1609711 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1436048745901850624)]} 0 4
[junit4:junit4] 2> 1609712 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 8
[junit4:junit4] 2> 1609716 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436048745910239232)]} 0 0
[junit4:junit4] 2> 1609720 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436048745913384960)]} 0 0
[junit4:junit4] 2> 1609721 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436048745913384960)]} 0 4
[junit4:junit4] 2> 1609724 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436048745919676416)]} 0 0
[junit4:junit4] 2> 1609731 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1436048745922822144)]} 0 1
[junit4:junit4] 2> 1609732 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436048745922822144)]} 0 5
[junit4:junit4] 2> 1609736 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1436048745931210752)]} 0 1
[junit4:junit4] 2> 1609745 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1436048745937502208)]} 0 1
[junit4:junit4] 2> 1609746 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1436048745937502208)]} 0 5
[junit4:junit4] 2> 1609746 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 7
[junit4:junit4] 2> 1609750 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436048745945890816)]} 0 1
[junit4:junit4] 2> 1609756 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1436048745949036544)]} 0 1
[junit4:junit4] 2> 1609756 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436048745949036544)]} 0 4
[junit4:junit4] 2> 1609759 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436048745956376576)]} 0 0
[junit4:junit4] 2> 1609765 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1436048745959522304)]} 0 0
[junit4:junit4] 2> 1609766 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436048745959522304)]} 0 4
[junit4:junit4] 2> 1609769 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436048745966862336)]} 0 0
[junit4:junit4] 2> 1609775 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1436048745970008064)]} 0 0
[junit4:junit4] 2> 1609776 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436048745970008064)]} 0 4
[junit4:junit4] 2> 1609779 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436048745977348096)]} 0 0
[junit4:junit4] 2> 1609785 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1436048745980493824)]} 0 0
[junit4:junit4] 2> 1609786 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436048745980493824)]} 0 4
[junit4:junit4] 2> 1609790 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436048745987833856)]} 0 1
[junit4:junit4] 2> 1609796 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1436048745992028160)]} 0 0
[junit4:junit4] 2> 1609797 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436048745992028160)]} 0 4
[junit4:junit4] 2> 1609800 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436048745999368192)]} 0 0
[junit4:junit4] 2> 1609806 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1436048746002513920)]} 0 0
[junit4:junit4] 2> 1609807 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436048746002513920)]} 0 4
[junit4:junit4] 2> 1609811 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436048746009853952)]} 0 1
[junit4:junit4] 2> 1609818 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1436048746015096832)]} 0 0
[junit4:junit4] 2> 1609819 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1436048746015096832)]} 0 4
[junit4:junit4] 2> 1609820 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 7
[junit4:junit4] 2> 1609822 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436048746022436864)]} 0 0
[junit4:junit4] 2> 1609828 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1436048746025582592)]} 0 0
[junit4:junit4] 2> 1609829 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436048746025582592)]} 0 4
[junit4:junit4] 2> 1609832 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436048746032922624)]} 0 0
[junit4:junit4] 2> 1609840 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1436048746038165504)]} 0 0
[junit4:junit4] 2> 1609841 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1436048746038165504)]} 0 4
[junit4:junit4] 2> 1609842 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 7
[junit4:junit4] 2> 1609846 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436048746046554112)]} 0 1
[junit4:junit4] 2> 1609854 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1436048746051796992)]} 0 1
[junit4:junit4] 2> 1609854 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1436048746051796992)]} 0 4
[junit4:junit4] 2> 1609855 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 7
[junit4:junit4] 2> 1609858 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436048746060185600)]} 0 0
[junit4:junit4] 2> 1609867 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1436048746065428480)]} 0 1
[junit4:junit4] 2> 1609867 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1436048746065428480)]} 0 4
[junit4:junit4] 2> 1609868 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 7
[junit4:junit4] 2> 1609871 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1436048746073817088)]} 0 0
[junit4:junit4] 2> 1609879 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1436048746079059968)]} 0 0
[junit4:junit4] 2> 1609880 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1436048746079059968)]} 0 4
[junit4:junit4] 2> 1609881 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 7
[junit4:junit4] 2> 1609883 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436048746086400000)]} 0 0
[junit4:junit4] 2> 1609889 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1436048746089545728)]} 0 0
[junit4:junit4] 2> 1609890 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436048746089545728)]} 0 4
[junit4:junit4] 2> 1609893 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436048746096885760)]} 0 0
[junit4:junit4] 2> 1609899 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1436048746100031488)]} 0 0
[junit4:junit4] 2> 1609900 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436048746100031488)]} 0 4
[junit4:junit4] 2> 1609903 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436048746107371520)]} 0 0
[junit4:junit4] 2> 1609909 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1436048746110517248)]} 0 1
[junit4:junit4] 2> 1609910 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436048746110517248)]} 0 4
[junit4:junit4] 2> 1609912 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1436048746116808704)]} 0 0
[junit4:junit4] 2> 1609920 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1436048746122051584)]} 0 0
[junit4:junit4] 2> 1609921 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1436048746122051584)]} 0 4
[junit4:junit4] 2> 1609922 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 7
[junit4:junit4] 2> 1609925 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436048746130440192)]} 0 0
[junit4:junit4] 2> 1609932 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1436048746133585920)]} 0 1
[junit4:junit4] 2> 1609932 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436048746133585920)]} 0 4
[junit4:junit4] 2> 1609935 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436048746140925952)]} 0 0
[junit4:junit4] 2> 1609943 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1436048746146168832)]} 0 0
[junit4:junit4] 2> 1609944 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[21 (1436048746146168832)]} 0 4
[junit4:junit4] 2> 1609945 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21]} 0 7
[junit4:junit4] 2> 1609948 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436048746154557440)]} 0 0
[junit4:junit4] 2> 1609956 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1436048746159800320)]} 0 0
[junit4:junit4] 2> 1609957 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1436048746159800320)]} 0 4
[junit4:junit4] 2> 1609958 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 7
[junit4:junit4] 2> 1609961 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436048746168188928)]} 0 0
[junit4:junit4] 2> 1609967 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1436048746171334656)]} 0 0
[junit4:junit4] 2> 1609968 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436048746171334656)]} 0 4
[junit4:junit4] 2> 1609971 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436048746178674688)]} 0 0
[junit4:junit4] 2> 1609979 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1436048746183917568)]} 0 0
[junit4:junit4] 2> 1609980 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1436048746183917568)]} 0 4
[junit4:junit4] 2> 1609981 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 7
[junit4:junit4] 2> 1609984 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436048746192306176)]} 0 0
[junit4:junit4] 2> 1609991 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1436048746195451904)]} 0 1
[junit4:junit4] 2> 1609992 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436048746195451904)]} 0 5
[junit4:junit4] 2> 1609994 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436048746202791936)]} 0 0
[junit4:junit4] 2> 1610002 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1436048746208034816)]} 0 0
[junit4:junit4] 2> 1610003 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1436048746208034816)]} 0 4
[junit4:junit4] 2> 1610004 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 7
[junit4:junit4] 2> 1610007 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436048746215374848)]} 0 1
[junit4:junit4] 2> 1610014 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1436048746220617728)]} 0 0
[junit4:junit4] 2> 1610015 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1436048746220617728)]} 0 4
[junit4:junit4] 2> 1610016 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 7
[junit4:junit4] 2> 1610019 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1436048746229006336)]} 0 0
[junit4:junit4] 2> 1610028 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1436048746234249216)]} 0 0
[junit4:junit4] 2> 1610028 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1436048746234249216)]} 0 4
[junit4:junit4] 2> 1610029 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 7
[junit4:junit4] 2> 1610032 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436048746242637824)]} 0 0
[junit4:junit4] 2> 1610040 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1436048746247880704)]} 0 0
[junit4:junit4] 2> 1610041 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1436048746247880704)]} 0 4
[junit4:junit4] 2> 1610042 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 7
[junit4:junit4] 2> 1610044 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436048746255220736)]} 0 0
[junit4:junit4] 2> 1610049 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1436048746258366464)]} 0 0
[junit4:junit4] 2> 1610050 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436048746258366464)]} 0 3
[junit4:junit4] 2> 1610053 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436048746264657920)]} 0 0
[junit4:junit4] 2> 1610059 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1436048746267803648)]} 0 0
[junit4:junit4] 2> 1610060 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436048746267803648)]} 0 4
[junit4:junit4] 2> 1610064 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436048746275143680)]} 0 1
[junit4:junit4] 2> 1610069 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1436048746278289408)]} 0 0
[junit4:junit4] 2> 1610070 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436048746278289408)]} 0 4
[junit4:junit4] 2> 1610073 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436048746285629440)]} 0 0
[junit4:junit4] 2> 1610079 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1436048746288775168)]} 0 0
[junit4:junit4] 2> 1610080 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436048746288775168)]} 0 4
[junit4:junit4] 2> 1610084 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436048746296115200)]} 0 1
[junit4:junit4] 2> 1610092 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1436048746301358080)]} 0 1
[junit4:junit4] 2> 1610092 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[34 (1436048746301358080)]} 0 4
[junit4:junit4] 2> 1610093 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34]} 0 7
[junit4:junit4] 2> 1610096 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436048746309746688)]} 0 0
[junit4:junit4] 2> 1610102 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1436048746312892416)]} 0 0
[junit4:junit4] 2> 1610103 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436048746312892416)]} 0 4
[junit4:junit4] 2> 1610107 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1436048746320232448)]} 0 1
[junit4:junit4] 2> 1610113 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1436048746325475328)]} 0 0
[junit4:junit4] 2> 1610114 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1436048746325475328)]} 0 3
[junit4:junit4] 2> 1610115 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 6
[junit4:junit4] 2> 1610117 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436048746331766784)]} 0 0
[junit4:junit4] 2> 1610122 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1436048746334912512)]} 0 0
[junit4:junit4] 2> 1610123 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436048746334912512)]} 0 3
[junit4:junit4] 2> 1610127 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436048746341203968)]} 0 1
[junit4:junit4] 2> 1610134 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1436048746346446848)]} 0 0
[junit4:junit4] 2> 1610135 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1436048746346446848)]} 0 4
[junit4:junit4] 2> 1610136 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 7
[junit4:junit4] 2> 1610139 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436048746354835456)]} 0 0
[junit4:junit4] 2> 1610145 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1436048746357981184)]} 0 0
[junit4:junit4] 2> 1610146 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436048746357981184)]} 0 4
[junit4:junit4] 2> 1610149 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436048746365321216)]} 0 0
[junit4:junit4] 2> 1610154 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1436048746368466944)]} 0 0
[junit4:junit4] 2> 1610155 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436048746368466944)]} 0 3
[junit4:junit4] 2> 1610159 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1436048746374758400)]} 0 1
[junit4:junit4] 2> 1610165 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1436048746378952704)]} 0 0
[junit4:junit4] 2> 1610166 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1436048746378952704)]} 0 4
[junit4:junit4] 2> 1610169 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1436048746386292736)]} 0 0
[junit4:junit4] 2> 1610174 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1436048746389438464)]} 0 0
[junit4:junit4] 2> 1610175 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1436048746389438464)]} 0 3
[junit4:junit4] 2> 1610178 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436048746395729920)]} 0 0
[junit4:junit4] 2> 1610184 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1436048746398875648)]} 0 0
[junit4:junit4] 2> 1610185 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436048746398875648)]} 0 4
[junit4:junit4] 2> 1610188 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436048746406215680)]} 0 0
[junit4:junit4] 2> 1610194 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1436048746409361408)]} 0 0
[junit4:junit4] 2> 1610195 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436048746409361408)]} 0 4
[junit4:junit4] 2> 1610198 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436048746416701440)]} 0 0
[junit4:junit4] 2> 1610204 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1436048746419847168)]} 0 0
[junit4:junit4] 2> 1610205 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436048746419847168)]} 0 4
[junit4:junit4] 2> 1610208 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436048746427187200)]} 0 0
[junit4:junit4] 2> 1610214 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1436048746430332928)]} 0 0
[junit4:junit4] 2> 1610215 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436048746430332928)]} 0 4
[junit4:junit4] 2> 1610219 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1436048746437672960)]} 0 1
[junit4:junit4] 2> 1610226 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1436048746442915840)]} 0 0
[junit4:junit4] 2> 1610227 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1436048746442915840)]} 0 4
[junit4:junit4] 2> 1610228 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 7
[junit4:junit4] 2> 1610231 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436048746450255872)]} 0 0
[junit4:junit4] 2> 1610238 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1436048746455498752)]} 0 0
[junit4:junit4] 2> 1610239 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1436048746455498752)]} 0 4
[junit4:junit4] 2> 1610240 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48]} 0 7
[junit4:junit4] 2> 1610243 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436048746462838784)]} 0 1
[junit4:junit4] 2> 1610249 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1436048746465984512)]} 0 1
[junit4:junit4] 2> 1610249 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436048746465984512)]} 0 4
[junit4:junit4] 2> 1610252 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1436048746473324544)]} 0 0
[junit4:junit4] 2> 1610258 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1436048746476470272)]} 0 0
[junit4:junit4] 2> 1610259 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1436048746476470272)]} 0 4
[junit4:junit4] 2> 1610262 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436048746483810304)]} 0 0
[junit4:junit4] 2> 1610267 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1436048746486956032)]} 0 0
[junit4:junit4] 2> 1610268 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436048746486956032)]} 0 3
[junit4:junit4] 2> 1610271 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436048746493247488)]} 0 0
[junit4:junit4] 2> 1610279 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1436048746498490368)]} 0 0
[junit4:junit4] 2> 1610280 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[52 (1436048746498490368)]} 0 4
[junit4:junit4] 2> 1610281 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52]} 0 7
[junit4:junit4] 2> 1610284 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436048746506878976)]} 0 0
[junit4:junit4] 2> 1610292 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1436048746512121856)]} 0 0
[junit4:junit4] 2> 1610293 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1436048746512121856)]} 0 4
[junit4:junit4] 2> 1610294 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 7
[junit4:junit4] 2> 1610296 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436048746519461888)]} 0 0
[junit4:junit4] 2> 1610305 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1436048746524704768)]} 0 1
[junit4:junit4] 2> 1610305 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1436048746524704768)]} 0 4
[junit4:junit4] 2> 1610306 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54]} 0 7
[junit4:junit4] 2> 1610309 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1436048746533093376)]} 0 0
[junit4:junit4] 2> 1610317 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1436048746538336256)]} 0 0
[junit4:junit4] 2> 1610318 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1436048746538336256)]} 0 4
[junit4:junit4] 2> 1610319 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 7
[junit4:junit4] 2> 1610322 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436048746546724864)]} 0 0
[junit4:junit4] 2> 1610328 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1436048746549870592)]} 0 0
[junit4:junit4] 2> 1610329 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436048746549870592)]} 0 4
[junit4:junit4] 2> 1610332 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436048746557210624)]} 0 0
[junit4:junit4] 2> 1610339 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1436048746560356352)]} 0 1
[junit4:junit4] 2> 1610340 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436048746560356352)]} 0 5
[junit4:junit4] 2> 1610342 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436048746567696384)]} 0 0
[junit4:junit4] 2> 1610349 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1436048746570842112)]} 0 1
[junit4:junit4] 2> 1610349 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436048746570842112)]} 0 4
[junit4:junit4] 2> 1610352 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436048746578182144)]} 0 0
[junit4:junit4] 2> 1610361 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1436048746583425024)]} 0 1
[junit4:junit4] 2> 1610361 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[59 (1436048746583425024)]} 0 4
[junit4:junit4] 2> 1610362 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59]} 0 7
[junit4:junit4] 2> 1610365 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436048746591813632)]} 0 0
[junit4:junit4] 2> 1610373 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1436048746597056512)]} 0 0
[junit4:junit4] 2> 1610374 T2930 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1436048746597056512)]} 0 4
[junit4:junit4] 2> 1610375 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 7
[junit4:junit4] 2> 1610377 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436048746604396544)]} 0 0
[junit4:junit4] 2> 1610382 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1436048746607542272)]} 0 0
[junit4:junit4] 2> 1610383 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436048746607542272)]} 0 3
[junit4:junit4] 2> 1610386 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436048746613833728)]} 0 0
[junit4:junit4] 2> 1610392 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1436048746616979456)]} 0 0
[junit4:junit4] 2> 1610393 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436048746616979456)]} 0 4
[junit4:junit4] 2> 1610396 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436048746624319488)]} 0 0
[junit4:junit4] 2> 1610402 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1436048746627465216)]} 0 0
[junit4:junit4] 2> 1610403 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436048746627465216)]} 0 4
[junit4:junit4] 2> 1610406 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436048746634805248)]} 0 0
[junit4:junit4] 2> 1610414 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1436048746640048128)]} 0 0
[junit4:junit4] 2> 1610415 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[64 (1436048746640048128)]} 0 4
[junit4:junit4] 2> 1610416 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64]} 0 7
[junit4:junit4] 2> 1610418 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436048746647388160)]} 0 0
[junit4:junit4] 2> 1610424 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1436048746650533888)]} 0 0
[junit4:junit4] 2> 1610425 T2914 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436048746650533888)]} 0 4
[junit4:junit4] 2> 1610428 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436048746657873920)]} 0 0
[junit4:junit4] 2> 1610437 T2942 C788 P44996 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63494/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1436048746664165376)]} 0 0
[junit4:junit4] 2> 1610438 T2912 C792 P63494 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[66 (1436048746664165376)]} 0 4
[junit4:junit4] 2> 1610439 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66]} 0 8
[junit4:junit4] 2> 1610442 T2888 C791 P63490 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1436048746671505408)]} 0 1
[junit4:junit4] 2> 1610448 T2957 C790 P52286 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:63497/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1436048746675699712)]} 0 0
[junit4:junit4] 2> 1610449 T2928 C789 P63497 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (143604874
[...truncated too long message...]
=collection1 url=http://127.0.0.1:52286 couldn't connect to http://127.0.0.1:63497/collection1/, counting as success
[junit4:junit4] 2> 1843297 T2967 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52286 DONE. sync succeeded
[junit4:junit4] 2> 1843297 T2967 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 1843299 T2967 oasc.ShardLeaderElectionContext.runLeaderProcess Sync was not a success but no one else is active! I am the leader
[junit4:junit4] 2> 1843299 T2967 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52286/collection1/
[junit4:junit4] 2> 1843299 T2967 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@52a00007
[junit4:junit4] 2> 1843300 T2967 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=642,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1843300 T2967 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1843300 T2967 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1843301 T2967 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1843303 T2967 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1843303 T2967 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1843304 T2967 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index;done=false>>]
[junit4:junit4] 2> 1843304 T2967 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4/index
[junit4:junit4] 2> 1843304 T2967 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4;done=false>>]
[junit4:junit4] 2> 1843304 T2967 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369522780135/jetty4
[junit4:junit4] 2> 1843304 T2967 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1843305 T2967 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89753044919386124-5-n_0000000001
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 1843305 T2967 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> 1843305 T2967 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1843306 T2967 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1843306 T2967 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> 1843306 T2967 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1843306 T2967 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=DummyCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=DUMMY, chunkSize=200), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=DUMMY, chunkSize=200)), sim=DefaultSimilarity, locale=ja_JP_JP_#u-ca-japanese, timezone=America/Dawson
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=3,free=113330560,total=244318208
[junit4:junit4] 2> NOTE: All tests run in this JVM: [ChaosMonkeyNothingIsSafeTest, SyncSliceTest, LukeRequestHandlerTest, PluginInfoTest, FileBasedSpellCheckerTest, TestLMDirichletSimilarityFactory, ZkControllerTest, SliceStateTest, TestCharFilters, TestSolrDeletionPolicy1, TestPHPSerializedResponseWriter, TestSolrDeletionPolicy2, TestReversedWildcardFilterFactory, SOLR749Test, QueryResultKeyTest, TestSearchPerf, BadCopyFieldTest, TestTrie, DirectSolrConnectionTest, TestPerFieldSimilarity, LoggingHandlerTest, AutoCommitTest, TestFuzzyAnalyzedSuggestions, BinaryUpdateRequestHandlerTest, StatelessScriptUpdateProcessorFactoryTest, BasicDistributedZkTest, TestLRUCache, TestWriterPerf, PrimUtilsTest, TestGroupingSearch, TestPluginEnable, TestCloudManagedSchemaAddField, TermsComponentTest, IndexSchemaTest, TestQueryUtils, TestLFUCache, UUIDFieldTest, ShowFileRequestHandlerTest, AlternateDirectoryTest, TestFunctionQuery, TestCloudManagedSchema, TestJoin, PolyFieldTest, TestSort, OverseerTest, SystemInfoHandlerTest, TestReplicationHandler, TestClassNameShortening, MBeansHandlerTest, SearchHandlerTest, TestFastLRUCache, ReturnFieldsTest, DocValuesTest, TestFieldCollectionResource, DistributedTermsComponentTest, TestSolrCoreProperties, ZkCLITest, SolrInfoMBeanTest, LeaderElectionTest, TestQuerySenderListener, UpdateRequestProcessorFactoryTest, TestSolrQueryParser, TestFaceting, SliceStateUpdateTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 260.14s, 1 test, 1 error <<< FAILURES!
[...truncated 406 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:380: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:360: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:1240: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 1 error, 13 ignored (7 assumptions)
Total time: 56 minutes 53 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure