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/06/22 15:08:35 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4083 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4083/
1 tests failed.
REGRESSION: org.apache.solr.cloud.RecoveryZkTest.testDistribSearch
Error Message:
expected:<230> but was:<42>
Stack Trace:
java.lang.AssertionError: expected:<230> but was:<42>
at __randomizedtesting.SeedInfo.seed([20A86B6850A159DE:A14EE57027FE39E2]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
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 9690 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 1222265 T3042 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1222270 T3042 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-RecoveryZkTest-1371905739796
[junit4:junit4] 2> 1222272 T3042 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1222272 T3043 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1222373 T3042 oasc.ZkTestServer.run start zk server on port:26370
[junit4:junit4] 2> 1222374 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1222378 T3049 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6dbab31c name:ZooKeeperConnection Watcher:127.0.0.1:26370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1222378 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1222379 T3042 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1222392 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1222394 T3051 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19a63a57 name:ZooKeeperConnection Watcher:127.0.0.1:26370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1222394 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1222395 T3042 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1222403 T3042 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1222410 T3042 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1222412 T3042 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1222415 T3042 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> 1222416 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1222427 T3042 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1222428 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1222533 T3042 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> 1222534 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1222537 T3042 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> 1222537 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1222546 T3042 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> 1222547 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1222550 T3042 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> 1222550 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1222553 T3042 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> 1222554 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1222557 T3042 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> 1222558 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1222560 T3042 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> 1222561 T3042 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1222841 T3042 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1222847 T3042 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:60630
[junit4:junit4] 2> 1222848 T3042 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1222848 T3042 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1222849 T3042 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.RecoveryZkTest-controljetty-1371905740094
[junit4:junit4] 2> 1222849 T3042 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.RecoveryZkTest-controljetty-1371905740094/solr.xml
[junit4:junit4] 2> 1222850 T3042 oasc.CoreContainer.<init> New CoreContainer 987203425
[junit4:junit4] 2> 1222850 T3042 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.RecoveryZkTest-controljetty-1371905740094/'
[junit4:junit4] 2> 1222851 T3042 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.RecoveryZkTest-controljetty-1371905740094/'
[junit4:junit4] 2> 1222979 T3042 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1222980 T3042 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1222980 T3042 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1222981 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1222981 T3042 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1222982 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1222982 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1222983 T3042 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1222983 T3042 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1222984 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1223002 T3042 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1223002 T3042 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:26370/solr
[junit4:junit4] 2> 1223003 T3042 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1223004 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1223007 T3062 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b8ef813 name:ZooKeeperConnection Watcher:127.0.0.1:26370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1223007 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1223031 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1223043 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1223065 T3064 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4584febf name:ZooKeeperConnection Watcher:127.0.0.1:26370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1223065 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1223092 T3042 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1223136 T3042 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1223202 T3042 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1223204 T3042 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60630_
[junit4:junit4] 2> 1223219 T3042 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60630_
[junit4:junit4] 2> 1223275 T3042 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1223344 T3042 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1223347 T3042 oasc.Overseer.start Overseer (id=89909214563729411-127.0.0.1:60630_-n_0000000000) starting
[junit4:junit4] 2> 1223357 T3042 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1223370 T3066 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1223370 T3042 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1223373 T3042 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1223380 T3042 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1223383 T3065 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1223388 T3067 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1223388 T3067 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1224886 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1224887 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60630_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60630"}
[junit4:junit4] 2> 1224887 T3065 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1224888 T3065 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1224906 T3064 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> 1225393 T3067 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.RecoveryZkTest-controljetty-1371905740094/collection1
[junit4:junit4] 2> 1225393 T3067 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1225394 T3067 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1225394 T3067 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1225396 T3067 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.RecoveryZkTest-controljetty-1371905740094/collection1/'
[junit4:junit4] 2> 1225397 T3067 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.RecoveryZkTest-controljetty-1371905740094/collection1/lib/README' to classloader
[junit4:junit4] 2> 1225398 T3067 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.RecoveryZkTest-controljetty-1371905740094/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1225450 T3067 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1225548 T3067 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1225650 T3067 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1225656 T3067 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1226261 T3067 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1226273 T3067 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1226277 T3067 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1226291 T3067 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1226296 T3067 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1226301 T3067 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1226302 T3067 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1226302 T3067 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1226303 T3067 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1226303 T3067 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1226304 T3067 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1226304 T3067 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1226304 T3067 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.RecoveryZkTest-controljetty-1371905740094/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/control/data/
[junit4:junit4] 2> 1226305 T3067 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@593aa24f
[junit4:junit4] 2> 1226305 T3067 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1226306 T3067 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/control/data
[junit4:junit4] 2> 1226306 T3067 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/control/data/index/
[junit4:junit4] 2> 1226307 T3067 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1371905739795/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1226307 T3067 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/control/data/index
[junit4:junit4] 2> 1226312 T3067 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2073da2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@60b4788),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1226312 T3067 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1226315 T3067 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1226316 T3067 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1226317 T3067 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1226317 T3067 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1226318 T3067 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1226318 T3067 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1226319 T3067 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1226319 T3067 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1226320 T3067 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1226336 T3067 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1226344 T3067 oass.SolrIndexSearcher.<init> Opening Searcher@d3f29dc main
[junit4:junit4] 2> 1226344 T3067 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/control/data/tlog
[junit4:junit4] 2> 1226346 T3067 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1226346 T3067 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1226350 T3068 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d3f29dc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1226351 T3067 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1226351 T3067 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60630 collection:control_collection shard:shard1
[junit4:junit4] 2> 1226352 T3067 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1226370 T3067 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1226384 T3067 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1226384 T3067 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1226384 T3067 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60630/collection1/
[junit4:junit4] 2> 1226384 T3067 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1226385 T3067 oasc.SyncStrategy.syncToMe http://127.0.0.1:60630/collection1/ has no replicas
[junit4:junit4] 2> 1226385 T3067 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60630/collection1/
[junit4:junit4] 2> 1226385 T3067 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1226410 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1226426 T3064 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> 1226450 T3067 oasc.ZkController.register We are http://127.0.0.1:60630/collection1/ and leader is http://127.0.0.1:60630/collection1/
[junit4:junit4] 2> 1226450 T3067 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60630
[junit4:junit4] 2> 1226450 T3067 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1226450 T3067 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1226451 T3067 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1226452 T3067 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1226453 T3042 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> 1226454 T3042 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1226454 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1226471 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1226472 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1226474 T3071 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@76a4cca name:ZooKeeperConnection Watcher:127.0.0.1:26370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1226474 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1226476 T3042 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1226478 T3042 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1226741 T3042 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1226744 T3042 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:10817
[junit4:junit4] 2> 1226745 T3042 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1226746 T3042 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1226746 T3042 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.RecoveryZkTest-jetty1-1371905744003
[junit4:junit4] 2> 1226747 T3042 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.RecoveryZkTest-jetty1-1371905744003/solr.xml
[junit4:junit4] 2> 1226747 T3042 oasc.CoreContainer.<init> New CoreContainer 120602151
[junit4:junit4] 2> 1226748 T3042 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.RecoveryZkTest-jetty1-1371905744003/'
[junit4:junit4] 2> 1226748 T3042 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.RecoveryZkTest-jetty1-1371905744003/'
[junit4:junit4] 2> 1226875 T3042 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1226875 T3042 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1226876 T3042 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1226876 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1226877 T3042 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1226877 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1226878 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1226878 T3042 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1226879 T3042 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1226879 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1226897 T3042 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1226898 T3042 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:26370/solr
[junit4:junit4] 2> 1226898 T3042 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1226899 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1226902 T3082 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51089e65 name:ZooKeeperConnection Watcher:127.0.0.1:26370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1226903 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1226917 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1226928 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1226930 T3084 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4beb9eb0 name:ZooKeeperConnection Watcher:127.0.0.1:26370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1226931 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1226942 T3042 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1227941 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1227942 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:60630__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60630_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60630"}
[junit4:junit4] 2> 1228045 T3042 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:10817_
[junit4:junit4] 2> 1228048 T3084 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> 1228048 T3071 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> 1228048 T3064 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> 1228049 T3042 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:10817_
[junit4:junit4] 2> 1228065 T3084 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> 1228065 T3064 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> 1228066 T3071 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1228066 T3071 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> 1228067 T3084 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1228067 T3064 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1228143 T3085 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1228143 T3085 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1229567 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1229568 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:10817_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10817"}
[junit4:junit4] 2> 1229568 T3065 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 1229569 T3065 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1229591 T3064 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> 1229591 T3071 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> 1229591 T3084 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> 1230152 T3085 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.RecoveryZkTest-jetty1-1371905744003/collection1
[junit4:junit4] 2> 1230152 T3085 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1230153 T3085 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1230153 T3085 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1230154 T3085 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.RecoveryZkTest-jetty1-1371905744003/collection1/'
[junit4:junit4] 2> 1230156 T3085 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.RecoveryZkTest-jetty1-1371905744003/collection1/lib/README' to classloader
[junit4:junit4] 2> 1230156 T3085 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.RecoveryZkTest-jetty1-1371905744003/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1230208 T3085 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1230268 T3085 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1230370 T3085 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1230376 T3085 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1230993 T3085 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1231005 T3085 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1231009 T3085 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1231023 T3085 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1231028 T3085 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1231032 T3085 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1231033 T3085 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1231033 T3085 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1231034 T3085 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1231034 T3085 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1231035 T3085 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1231035 T3085 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1231035 T3085 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.RecoveryZkTest-jetty1-1371905744003/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty1/
[junit4:junit4] 2> 1231036 T3085 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@593aa24f
[junit4:junit4] 2> 1231036 T3085 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1231037 T3085 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty1
[junit4:junit4] 2> 1231037 T3085 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty1/index/
[junit4:junit4] 2> 1231038 T3085 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1231038 T3085 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty1/index
[junit4:junit4] 2> 1231042 T3085 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38c9d6b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237d7328),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1231042 T3085 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1231045 T3085 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1231046 T3085 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1231046 T3085 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1231047 T3085 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1231048 T3085 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1231048 T3085 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1231048 T3085 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1231049 T3085 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1231050 T3085 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1231066 T3085 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1231073 T3085 oass.SolrIndexSearcher.<init> Opening Searcher@5afaf245 main
[junit4:junit4] 2> 1231073 T3085 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty1/tlog
[junit4:junit4] 2> 1231075 T3085 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1231075 T3085 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1231079 T3086 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5afaf245 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1231081 T3085 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1231082 T3085 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:10817 collection:collection1 shard:shard1
[junit4:junit4] 2> 1231082 T3085 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1231105 T3085 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1231108 T3085 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1231108 T3085 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1231108 T3085 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:10817/collection1/
[junit4:junit4] 2> 1231108 T3085 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1231109 T3085 oasc.SyncStrategy.syncToMe http://127.0.0.1:10817/collection1/ has no replicas
[junit4:junit4] 2> 1231109 T3085 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:10817/collection1/
[junit4:junit4] 2> 1231109 T3085 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1232606 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1232659 T3064 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> 1232659 T3084 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> 1232659 T3071 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> 1232714 T3085 oasc.ZkController.register We are http://127.0.0.1:10817/collection1/ and leader is http://127.0.0.1:10817/collection1/
[junit4:junit4] 2> 1232714 T3085 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:10817
[junit4:junit4] 2> 1232714 T3085 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1232714 T3085 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1232715 T3085 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1232716 T3085 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1232717 T3042 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> 1232718 T3042 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1232719 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1233005 T3042 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1233008 T3042 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:31504
[junit4:junit4] 2> 1233009 T3042 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1233009 T3042 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1233010 T3042 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.RecoveryZkTest-jetty2-1371905750260
[junit4:junit4] 2> 1233010 T3042 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.RecoveryZkTest-jetty2-1371905750260/solr.xml
[junit4:junit4] 2> 1233011 T3042 oasc.CoreContainer.<init> New CoreContainer 1768880862
[junit4:junit4] 2> 1233012 T3042 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.RecoveryZkTest-jetty2-1371905750260/'
[junit4:junit4] 2> 1233012 T3042 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.RecoveryZkTest-jetty2-1371905750260/'
[junit4:junit4] 2> 1233141 T3042 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1233142 T3042 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1233143 T3042 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1233143 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1233144 T3042 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1233144 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1233145 T3042 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1233145 T3042 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1233146 T3042 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1233146 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1233162 T3042 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1233163 T3042 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:26370/solr
[junit4:junit4] 2> 1233163 T3042 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1233164 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1233174 T3098 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a4ad4e2 name:ZooKeeperConnection Watcher:127.0.0.1:26370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1233174 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1233193 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1233203 T3042 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1233205 T3100 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4103ff42 name:ZooKeeperConnection Watcher:127.0.0.1:26370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1233206 T3042 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1233221 T3042 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1234174 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1234175 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:10817__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:10817_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10817"}
[junit4:junit4] 2> 1234193 T3100 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> 1234193 T3064 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> 1234193 T3084 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> 1234193 T3071 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> 1234226 T3042 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:31504_
[junit4:junit4] 2> 1234228 T3042 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:31504_
[junit4:junit4] 2> 1234230 T3064 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> 1234230 T3084 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> 1234230 T3071 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1234230 T3100 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1234231 T3071 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> 1234231 T3100 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> 1234232 T3064 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1234238 T3084 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1234244 T3101 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1234244 T3101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1235697 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1235698 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31504_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31504"}
[junit4:junit4] 2> 1235698 T3065 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1235699 T3065 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1235716 T3064 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> 1235716 T3071 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> 1235716 T3100 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> 1235716 T3084 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> 1236249 T3101 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.RecoveryZkTest-jetty2-1371905750260/collection1
[junit4:junit4] 2> 1236249 T3101 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1236250 T3101 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1236250 T3101 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1236251 T3101 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.RecoveryZkTest-jetty2-1371905750260/collection1/'
[junit4:junit4] 2> 1236253 T3101 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.RecoveryZkTest-jetty2-1371905750260/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1236253 T3101 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.RecoveryZkTest-jetty2-1371905750260/collection1/lib/README' to classloader
[junit4:junit4] 2> 1236306 T3101 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1236367 T3101 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1236470 T3101 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1236476 T3101 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1237091 T3101 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1237104 T3101 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1237108 T3101 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1237122 T3101 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1237126 T3101 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1237130 T3101 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1237131 T3101 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1237132 T3101 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1237132 T3101 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1237133 T3101 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1237133 T3101 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1237134 T3101 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1237134 T3101 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.RecoveryZkTest-jetty2-1371905750260/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/
[junit4:junit4] 2> 1237134 T3101 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@593aa24f
[junit4:junit4] 2> 1237135 T3101 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1237136 T3101 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2
[junit4:junit4] 2> 1237137 T3101 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index/
[junit4:junit4] 2> 1237137 T3101 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1237137 T3101 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index
[junit4:junit4] 2> 1237141 T3101 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1237141 T3101 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1237144 T3101 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1237144 T3101 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1237145 T3101 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1237146 T3101 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1237146 T3101 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1237146 T3101 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1237147 T3101 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1237147 T3101 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1237148 T3101 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1237163 T3101 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1237169 T3101 oass.SolrIndexSearcher.<init> Opening Searcher@343734b5 main
[junit4:junit4] 2> 1237170 T3101 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/tlog
[junit4:junit4] 2> 1237171 T3101 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1237171 T3101 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1237176 T3102 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@343734b5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1237178 T3101 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1237178 T3101 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:31504 collection:collection1 shard:shard1
[junit4:junit4] 2> 1237181 T3101 oasc.ZkController.register We are http://127.0.0.1:31504/collection1/ and leader is http://127.0.0.1:10817/collection1/
[junit4:junit4] 2> 1237181 T3101 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:31504
[junit4:junit4] 2> 1237182 T3101 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1237182 T3101 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C528 name=collection1 org.apache.solr.core.SolrCore@55a6d031 url=http://127.0.0.1:31504/collection1 node=127.0.0.1:31504_ C528_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:31504_, base_url=http://127.0.0.1:31504}
[junit4:junit4] 2> 1237182 T3103 C528 P31504 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1237182 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1237183 T3103 C528 P31504 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1237183 T3103 C528 P31504 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1237184 T3103 C528 P31504 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1237184 T3042 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> 1237185 T3042 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1237185 T3103 C528 P31504 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1237185 T3042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1237203 T3042 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1237204 T3074 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:31504__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C529 name=collection1 org.apache.solr.core.SolrCore@7e54ea77 url=http://127.0.0.1:60630/collection1 node=127.0.0.1:60630_ C529_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:60630_, base_url=http://127.0.0.1:60630, leader=true}
[junit4:junit4] 2> 1237217 T3055 C529 P60630 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2073da2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@60b4788),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1237218 T3055 C529 P60630 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1237222 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1237223 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:31504__collection1",
[junit4:junit4] 2> "numShards":"1",
[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:31504_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31504"}
[junit4:junit4] 2> 1237223 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438547448682250240)]} 0 8
[junit4:junit4] 2> 1237223 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10001 (1438547448682250241)]} 0 8
[junit4:junit4] 2> 1237235 T3100 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> 1237235 T3071 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> 1237235 T3084 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> 1237235 T3064 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> ASYNC NEW_CORE C530 name=collection1 org.apache.solr.core.SolrCore@65e3ec36 url=http://127.0.0.1:10817/collection1 node=127.0.0.1:10817_ C530_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:10817_, base_url=http://127.0.0.1:10817, leader=true}
[junit4:junit4] 2> 1237243 T3075 C530 P10817 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38c9d6b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237d7328),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1237244 T3075 C530 P10817 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> C528_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:31504_, base_url=http://127.0.0.1:31504}
[junit4:junit4] 2> 1237257 T3090 C528 P31504 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1237258 T3090 C528 P31504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1237260 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438547448709513216)]} 0 5
[junit4:junit4] 2> 1237260 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10001 (1438547448709513217)]} 0 5
[junit4:junit4] 2> 1237261 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438547448709513216)]} 0 21
[junit4:junit4] 2> 1237261 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10001 (1438547448709513217)]} 0 21
[junit4:junit4] 2> 1237313 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10002 (1438547448783962112)]} 0 1
[junit4:junit4] 2> 1237314 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438547448785010688)]} 0 1
[junit4:junit4] 2> 1237320 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10002 (1438547448788156416)]} 0 1
[junit4:junit4] 2> 1237320 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1438547448788156417)]} 0 1
[junit4:junit4] 2> 1237320 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10002 (1438547448788156416)]} 0 4
[junit4:junit4] 2> 1237321 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438547448788156417)]} 0 5
[junit4:junit4] 2> 1237415 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438547448890916864)]} 0 1
[junit4:junit4] 2> 1237415 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10003 (1438547448890916865)]} 0 1
[junit4:junit4] 2> 1237422 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10003 (1438547448895111169)]} 0 1
[junit4:junit4] 2> 1237422 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1438547448895111168)]} 0 1
[junit4:junit4] 2> 1237422 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10003 (1438547448895111169)]} 0 4
[junit4:junit4] 2> 1237423 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438547448895111168)]} 0 5
[junit4:junit4] 2> 1237517 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10004 (1438547448997871616)]} 0 1
[junit4:junit4] 2> 1237518 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1438547448998920192)]} 0 1
[junit4:junit4] 2> 1237524 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10004 (1438547449002065920)]} 0 1
[junit4:junit4] 2> 1237524 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10004 (1438547449002065920)]} 0 4
[junit4:junit4] 2> 1237525 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1438547449002065921)]} 0 1
[junit4:junit4] 2> 1237525 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1438547449002065921)]} 0 5
[junit4:junit4] 2> 1237611 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10005 (1438547449096437760)]} 0 1
[junit4:junit4] 2> 1237612 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1438547449097486336)]} 0 1
[junit4:junit4] 2> 1237618 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10005 (1438547449100632064)]} 0 1
[junit4:junit4] 2> 1237618 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10005 (1438547449100632064)]} 0 4
[junit4:junit4] 2> 1237619 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1438547449101680640)]} 0 1
[junit4:junit4] 2> 1237619 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1438547449101680640)]} 0 4
[junit4:junit4] 2> 1237722 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10006 (1438547449212829696)]} 0 1
[junit4:junit4] 2> 1237723 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1438547449213878272)]} 0 1
[junit4:junit4] 2> 1237728 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10006 (1438547449215975424)]} 0 1
[junit4:junit4] 2> 1237728 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10006 (1438547449215975424)]} 0 4
[junit4:junit4] 2> 1237729 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1438547449217024000)]} 0 1
[junit4:junit4] 2> 1237730 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1438547449217024000)]} 0 5
[junit4:junit4] 2> 1237817 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10006 (-1438547449312444416)]} 0 1
[junit4:junit4] 2> 1237817 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[6 (-1438547449312444417)]} 0 1
[junit4:junit4] 2> 1237824 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10006 (-1438547449316638720)]} 0 1
[junit4:junit4] 2> 1237824 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[6 (-1438547449316638721)]} 0 1
[junit4:junit4] 2> 1237824 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10006 (-1438547449316638720)]} 0 4
[junit4:junit4] 2> 1237825 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[6 (-1438547449316638721)]} 0 5
[junit4:junit4] 2> 1237829 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10007 (1438547449325027328)]} 0 1
[junit4:junit4] 2> 1237829 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1438547449325027329)]} 0 1
[junit4:junit4] 2> 1237836 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1438547449329221632)]} 0 1
[junit4:junit4] 2> 1237836 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10007 (1438547449329221633)]} 0 1
[junit4:junit4] 2> 1237836 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1438547449329221632)]} 0 4
[junit4:junit4] 2> 1237837 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10007 (1438547449329221633)]} 0 5
[junit4:junit4] 2> 1237866 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1438547449363824640)]} 0 1
[junit4:junit4] 2> 1237867 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10008 (1438547449364873216)]} 0 1
[junit4:junit4] 2> 1237873 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10008 (1438547449368018944)]} 0 1
[junit4:junit4] 2> 1237873 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1438547449366970368)]} 0 1
[junit4:junit4] 2> 1237873 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10008 (1438547449368018944)]} 0 4
[junit4:junit4] 2> 1237874 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1438547449366970368)]} 0 6
[junit4:junit4] 2> 1237897 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10008 (-1438547449397379072)]} 0 0
[junit4:junit4] 2> 1237898 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[8 (-1438547449398427648)]} 0 0
[junit4:junit4] 2> 1237902 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10008 (-1438547449400524800)]} 0 0
[junit4:junit4] 2> 1237903 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10008 (-1438547449400524800)]} 0 3
[junit4:junit4] 2> 1237903 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[8 (-1438547449401573376)]} 0 0
[junit4:junit4] 2> 1237904 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[8 (-1438547449401573376)]} 0 3
[junit4:junit4] 2> 1237906 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1438547449405767680)]} 0 1
[junit4:junit4] 2> 1237906 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10009 (1438547449405767681)]} 0 1
[junit4:junit4] 2> 1237912 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1438547449408913408)]} 0 1
[junit4:junit4] 2> 1237912 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1438547449408913408)]} 0 4
[junit4:junit4] 2> 1237913 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10009 (1438547449409961984)]} 0 1
[junit4:junit4] 2> 1237913 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10009 (1438547449409961984)]} 0 4
[junit4:junit4] 2> 1238006 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1438547449510625280)]} 0 1
[junit4:junit4] 2> 1238007 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10010 (1438547449511673856)]} 0 1
[junit4:junit4] 2> 1238013 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1438547449514819584)]} 0 1
[junit4:junit4] 2> 1238013 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10010 (1438547449514819585)]} 0 1
[junit4:junit4] 2> 1238013 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1438547449514819584)]} 0 4
[junit4:junit4] 2> 1238014 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10010 (1438547449514819585)]} 0 5
[junit4:junit4] 2> 1238018 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10 (-1438547449524256768)]} 0 0
[junit4:junit4] 2> 1238018 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10010 (-1438547449524256769)]} 0 0
[junit4:junit4] 2> 1238023 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10010 (-1438547449527402496)]} 0 0
[junit4:junit4] 2> 1238023 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10 (-1438547449527402497)]} 0 0
[junit4:junit4] 2> 1238024 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10010 (-1438547449527402496)]} 0 3
[junit4:junit4] 2> 1238024 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10 (-1438547449527402497)]} 0 3
[junit4:junit4] 2> 1238028 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10011 (1438547449533693953)]} 0 1
[junit4:junit4] 2> 1238028 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1438547449533693952)]} 0 1
[junit4:junit4] 2> 1238034 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10011 (1438547449536839680)]} 0 1
[junit4:junit4] 2> 1238034 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10011 (1438547449536839680)]} 0 4
[junit4:junit4] 2> 1238035 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1438547449537888256)]} 0 1
[junit4:junit4] 2> 1238035 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1438547449537888256)]} 0 4
[junit4:junit4] 2> 1238058 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10012 (1438547449565151232)]} 0 1
[junit4:junit4] 2> 1238059 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1438547449566199808)]} 0 1
[junit4:junit4] 2> 1238066 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1438547449570394112)]} 0 1
[junit4:junit4] 2> 1238066 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10012 (1438547449569345536)]} 0 1
[junit4:junit4] 2> 1238066 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1438547449570394112)]} 0 4
[junit4:junit4] 2> 1238067 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10012 (1438547449569345536)]} 0 6
[junit4:junit4] 2> 1238120 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[12 (-1438547449631211520)]} 0 0
[junit4:junit4] 2> 1238121 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10012 (-1438547449632260096)]} 0 0
[junit4:junit4] 2> 1238127 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[12 (-1438547449635405824)]} 0 0
[junit4:junit4] 2> 1238127 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10012 (-1438547449636454400)]} 0 0
[junit4:junit4] 2> 1238128 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[12 (-1438547449635405824)]} 0 4
[junit4:junit4] 2> 1238128 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10012 (-1438547449636454400)]} 0 3
[junit4:junit4] 2> 1238132 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10013 (1438547449642745856)]} 0 1
[junit4:junit4] 2> 1238132 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1438547449642745857)]} 0 1
[junit4:junit4] 2> 1238138 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10013 (1438547449645891584)]} 0 1
[junit4:junit4] 2> 1238138 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10013 (1438547449645891584)]} 0 4
[junit4:junit4] 2> 1238139 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1438547449646940160)]} 0 1
[junit4:junit4] 2> 1238139 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1438547449646940160)]} 0 4
[junit4:junit4] 2> 1238184 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10013 (-1438547449698320384)]} 0 0
[junit4:junit4] 2> 1238185 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[13 (-1438547449699368960)]} 0 0
[junit4:junit4] 2> 1238190 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[13 (-1438547449702514689)]} 0 0
[junit4:junit4] 2> 1238190 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10013 (-1438547449702514688)]} 0 0
[junit4:junit4] 2> 1238191 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[13 (-1438547449702514689)]} 0 3
[junit4:junit4] 2> 1238191 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10013 (-1438547449702514688)]} 0 3
[junit4:junit4] 2> 1238196 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1438547449709854721)]} 0 1
[junit4:junit4] 2> 1238196 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10014 (1438547449709854720)]} 0 1
[junit4:junit4] 2> 1238203 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1438547449714049024)]} 0 1
[junit4:junit4] 2> 1238203 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1438547449714049024)]} 0 4
[junit4:junit4] 2> 1238204 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10014 (1438547449715097600)]} 0 1
[junit4:junit4] 2> 1238205 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10014 (1438547449715097600)]} 0 5
[junit4:junit4] 2> 1238206 T3074 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:31504__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1238206 T3074 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:31504__collection1&state=recovering&nodeName=127.0.0.1:31504_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 1238242 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[14 (-1438547449759137792)]} 0 0
[junit4:junit4] 2> 1238243 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10014 (-1438547449760186368)]} 0 0
[junit4:junit4] 2> 1238248 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[14 (-1438547449763332096)]} 0 0
[junit4:junit4] 2> 1238249 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[14 (-1438547449763332096)]} 0 3
[junit4:junit4] 2> 1238249 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10014 (-1438547449764380672)]} 0 0
[junit4:junit4] 2> 1238250 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10014 (-1438547449764380672)]} 0 3
[junit4:junit4] 2> 1238253 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1438547449769623552)]} 0 1
[junit4:junit4] 2> 1238254 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10015 (1438547449770672128)]} 0 1
[junit4:junit4] 2> 1238259 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1438547449772769280)]} 0 1
[junit4:junit4] 2> 1238259 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1438547449772769280)]} 0 4
[junit4:junit4] 2> 1238261 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10015 (1438547449773817856)]} 0 1
[junit4:junit4] 2> 1238261 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10015 (1438547449773817856)]} 0 5
[junit4:junit4] 2> 1238273 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1438547449790595072)]} 0 1
[junit4:junit4] 2> 1238275 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10016 (1438547449792692224)]} 0 1
[junit4:junit4] 2> 1238280 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1438547449794789376)]} 0 1
[junit4:junit4] 2> 1238281 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10016 (1438547449795837952)]} 0 1
[junit4:junit4] 2> 1238281 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1438547449794789376)]} 0 5
[junit4:junit4] 2> 1238282 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10016 (1438547449795837952)]} 0 5
[junit4:junit4] 2> 1238303 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[16 (-1438547449823100928)]} 0 0
[junit4:junit4] 2> 1238304 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10016 (-1438547449824149504)]} 0 0
[junit4:junit4] 2> 1238308 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[16 (-1438547449826246656)]} 0 0
[junit4:junit4] 2> 1238309 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[16 (-1438547449826246656)]} 0 3
[junit4:junit4] 2> 1238310 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10016 (-1438547449827295232)]} 0 0
[junit4:junit4] 2> 1238311 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10016 (-1438547449827295232)]} 0 4
[junit4:junit4] 2> 1238313 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1438547449832538112)]} 0 1
[junit4:junit4] 2> 1238315 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10017 (1438547449834635264)]} 0 1
[junit4:junit4] 2> 1238319 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1438547449835683840)]} 0 1
[junit4:junit4] 2> 1238319 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1438547449835683840)]} 0 4
[junit4:junit4] 2> 1238321 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10017 (1438547449837780992)]} 0 1
[junit4:junit4] 2> 1238321 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10017 (1438547449837780992)]} 0 4
[junit4:junit4] 2> 1238386 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1438547449909084160)]} 0 1
[junit4:junit4] 2> 1238388 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10018 (1438547449911181312)]} 0 1
[junit4:junit4] 2> 1238393 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1438547449913278464)]} 0 1
[junit4:junit4] 2> 1238393 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1438547449913278464)]} 0 4
[junit4:junit4] 2> 1238394 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1438547449914327040)]} 0 1
[junit4:junit4] 2> 1238394 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10018 (1438547449914327040)]} 0 4
[junit4:junit4] 2> 1238427 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1438547449952075776)]} 0 1
[junit4:junit4] 2> 1238429 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10019 (1438547449954172928)]} 0 1
[junit4:junit4] 2> 1238433 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1438547449955221504)]} 0 1
[junit4:junit4] 2> 1238433 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1438547449955221504)]} 0 4
[junit4:junit4] 2> 1238436 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1438547449957318656)]} 0 1
[junit4:junit4] 2> 1238436 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10019 (1438547449957318656)]} 0 5
[junit4:junit4] 2> 1238458 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[18 (-1438547449985630208)]} 0 0
[junit4:junit4] 2> 1238461 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10018 (-1438547449988775936)]} 0 0
[junit4:junit4] 2> 1238463 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[18 (-1438547449988775936)]} 0 0
[junit4:junit4] 2> 1238464 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[18 (-1438547449988775936)]} 0 3
[junit4:junit4] 2> 1238467 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10018 (-1438547449991921664)]} 0 0
[junit4:junit4] 2> 1238468 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1438547449995067392)]} 0 1
[junit4:junit4] 2> 1238468 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10018 (-1438547449991921664)]} 0 4
[junit4:junit4] 2> 1238472 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10020 (1438547449999261696)]} 0 1
[junit4:junit4] 2> 1238475 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1438547449998213120)]} 0 1
[junit4:junit4] 2> 1238475 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1438547449998213120)]} 0 5
[junit4:junit4] 2> 1238478 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1438547450002407424)]} 0 1
[junit4:junit4] 2> 1238478 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10020 (1438547450002407424)]} 0 4
[junit4:junit4] 2> 1238529 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[20 (-1438547450060079104)]} 0 0
[junit4:junit4] 2> 1238533 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10020 (-1438547450064273408)]} 0 0
[junit4:junit4] 2> 1238536 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[20 (-1438547450064273408)]} 0 0
[junit4:junit4] 2> 1238537 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[20 (-1438547450064273408)]} 0 4
[junit4:junit4] 2> 1238538 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10020 (-1438547450067419136)]} 0 0
[junit4:junit4] 2> 1238539 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10020 (-1438547450067419136)]} 0 3
[junit4:junit4] 2> 1238541 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1438547450071613440)]} 0 1
[junit4:junit4] 2> 1238543 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10021 (1438547450073710592)]} 0 1
[junit4:junit4] 2> 1238547 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1438547450074759168)]} 0 1
[junit4:junit4] 2> 1238547 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1438547450074759168)]} 0 4
[junit4:junit4] 2> 1238549 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1438547450076856320)]} 0 1
[junit4:junit4] 2> 1238549 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10021 (1438547450076856320)]} 0 4
[junit4:junit4] 2> 1238586 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[21 (-1438547450119847936)]} 0 0
[junit4:junit4] 2> 1238588 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10021 (-1438547450121945088)]} 0 0
[junit4:junit4] 2> 1238591 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[21 (-1438547450122993664)]} 0 0
[junit4:junit4] 2> 1238592 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[21 (-1438547450122993664)]} 0 3
[junit4:junit4] 2> 1238595 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10021 (-1438547450126139392)]} 0 0
[junit4:junit4] 2> 1238596 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1438547450129285120)]} 0 1
[junit4:junit4] 2> 1238596 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10021 (-1438547450126139392)]} 0 4
[junit4:junit4] 2> 1238600 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10022 (1438547450133479424)]} 0 1
[junit4:junit4] 2> 1238603 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1438547450132430848)]} 0 1
[junit4:junit4] 2> 1238603 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1438547450132430848)]} 0 5
[junit4:junit4] 2> 1238608 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1438547450137673728)]} 0 1
[junit4:junit4] 2> 1238608 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10022 (1438547450137673728)]} 0 5
[junit4:junit4] 2> 1238681 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[22 (-1438547450219462656)]} 0 0
[junit4:junit4] 2> 1238686 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10022 (-1438547450224705536)]} 0 0
[junit4:junit4] 2> 1238687 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[22 (-1438547450223656960)]} 0 0
[junit4:junit4] 2> 1238688 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[22 (-1438547450223656960)]} 0 3
[junit4:junit4] 2> 1238691 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10022 (-1438547450227851264)]} 0 0
[junit4:junit4] 2> 1238692 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1438547450229948416)]} 0 1
[junit4:junit4] 2> 1238692 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10022 (-1438547450227851264)]} 0 3
[junit4:junit4] 2> 1238696 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10023 (1438547450234142720)]} 0 1
[junit4:junit4] 2> 1238699 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1438547450233094144)]} 0 1
[junit4:junit4] 2> 1238699 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1438547450233094144)]} 0 5
[junit4:junit4] 2> 1238703 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1438547450237288448)]} 0 1
[junit4:junit4] 2> 1238703 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10023 (1438547450237288448)]} 0 5
[junit4:junit4] 2> 1238720 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1438547450259308544)]} 0 1
[junit4:junit4] 2> 1238723 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10024 (1438547450262454272)]} 0 1
[junit4:junit4] 2> 1238727 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1438547450262454272)]} 0 1
[junit4:junit4] 2> 1238727 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1438547450262454272)]} 0 5
[junit4:junit4] 2> 1238730 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1438547450266648576)]} 0 1
[junit4:junit4] 2> 1238730 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10024 (1438547450266648576)]} 0 4
[junit4:junit4] 2> 1238769 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[24 (-1438547450311737344)]} 0 0
[junit4:junit4] 2> 1238771 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10024 (-1438547450313834496)]} 0 0
[junit4:junit4] 2> 1238774 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[24 (-1438547450314883072)]} 0 0
[junit4:junit4] 2> 1238775 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[24 (-1438547450314883072)]} 0 3
[junit4:junit4] 2> 1238776 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10024 (-1438547450316980224)]} 0 0
[junit4:junit4] 2> 1238777 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10024 (-1438547450316980224)]} 0 3
[junit4:junit4] 2> 1238779 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1438547450321174528)]} 0 1
[junit4:junit4] 2> 1238781 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10025 (1438547450323271680)]} 0 1
[junit4:junit4] 2> 1238785 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1438547450324320256)]} 0 1
[junit4:junit4] 2> 1238785 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1438547450324320256)]} 0 4
[junit4:junit4] 2> 1238787 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1438547450326417408)]} 0 1
[junit4:junit4] 2> 1238787 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10025 (1438547450326417408)]} 0 4
[junit4:junit4] 2> 1238810 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1438547450353680384)]} 0 1
[junit4:junit4] 2> 1238812 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10026 (1438547450355777536)]} 0 1
[junit4:junit4] 2> 1238816 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1438547450356826112)]} 0 1
[junit4:junit4] 2> 1238816 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1438547450356826112)]} 0 4
[junit4:junit4] 2> 1238818 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1438547450358923264)]} 0 1
[junit4:junit4] 2> 1238818 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10026 (1438547450358923264)]} 0 4
[junit4:junit4] 2> 1238852 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[25 (-1438547450398769152)]} 0 0
[junit4:junit4] 2> 1238854 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10025 (-1438547450400866304)]} 0 0
[junit4:junit4] 2> 1238857 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[25 (-1438547450401914880)]} 0 0
[junit4:junit4] 2> 1238858 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[25 (-1438547450401914880)]} 0 3
[junit4:junit4] 2> 1238860 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10025 (-1438547450404012032)]} 0 0
[junit4:junit4] 2> 1238861 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10025 (-1438547450404012032)]} 0 4
[junit4:junit4] 2> 1238862 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1438547450408206336)]} 0 1
[junit4:junit4] 2> 1238866 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10027 (1438547450412400640)]} 0 1
[junit4:junit4] 2> 1238870 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1438547450412400640)]} 0 1
[junit4:junit4] 2> 1238870 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1438547450412400640)]} 0 5
[junit4:junit4] 2> 1238873 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1438547450416594944)]} 0 1
[junit4:junit4] 2> 1238873 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10027 (1438547450416594944)]} 0 4
[junit4:junit4] 2> 1238963 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1438547450514112512)]} 0 1
[junit4:junit4] 2> 1238966 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10028 (1438547450517258240)]} 0 1
[junit4:junit4] 2> 1238969 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1438547450517258240)]} 0 1
[junit4:junit4] 2> 1238969 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1438547450517258240)]} 0 4
[junit4:junit4] 2> 1238972 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1438547450520403968)]} 0 1
[junit4:junit4] 2> 1238972 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10028 (1438547450520403968)]} 0 4
[junit4:junit4] 2> 1239045 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1438547450600095744)]} 0 1
[junit4:junit4] 2> 1239048 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10029 (1438547450603241472)]} 0 1
[junit4:junit4] 2> 1239051 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1438547450603241472)]} 0 1
[junit4:junit4] 2> 1239051 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1438547450603241472)]} 0 4
[junit4:junit4] 2> 1239055 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1438547450607435776)]} 0 1
[junit4:junit4] 2> 1239055 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10029 (1438547450607435776)]} 0 4
[junit4:junit4] 2> 1239095 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1438547450652524544)]} 0 1
[junit4:junit4] 2> 1239099 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10030 (1438547450656718848)]} 0 1
[junit4:junit4] 2> 1239102 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1438547450656718848)]} 0 1
[junit4:junit4] 2> 1239102 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1438547450656718848)]} 0 4
[junit4:junit4] 2> 1239105 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1438547450659864576)]} 0 1
[junit4:junit4] 2> 1239105 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10030 (1438547450659864576)]} 0 4
[junit4:junit4] 2> 1239144 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[29 (-1438547450704953344)]} 0 0
[junit4:junit4] 2> 1239147 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10029 (-1438547450708099072)]} 0 0
[junit4:junit4] 2> 1239149 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[29 (-1438547450708099072)]} 0 0
[junit4:junit4] 2> 1239150 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[29 (-1438547450708099072)]} 0 3
[junit4:junit4] 2> 1239152 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10029 (-1438547450711244800)]} 0 0
[junit4:junit4] 2> 1239153 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1438547450713341952)]} 0 1
[junit4:junit4] 2> 1239153 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10029 (-1438547450711244800)]} 0 3
[junit4:junit4] 2> 1239157 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10031 (1438547450717536256)]} 0 1
[junit4:junit4] 2> 1239160 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1438547450717536256)]} 0 1
[junit4:junit4] 2> 1239160 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1438547450717536256)]} 0 4
[junit4:junit4] 2> 1239163 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1438547450720681984)]} 0 1
[junit4:junit4] 2> 1239163 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10031 (1438547450720681984)]} 0 4
[junit4:junit4] 2> 1239191 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[31 (-1438547450754236416)]} 0 0
[junit4:junit4] 2> 1239193 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10031 (-1438547450756333568)]} 0 0
[junit4:junit4] 2> 1239196 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[31 (-1438547450757382144)]} 0 0
[junit4:junit4] 2> 1239197 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[31 (-1438547450757382144)]} 0 3
[junit4:junit4] 2> 1239198 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10031 (-1438547450759479296)]} 0 0
[junit4:junit4] 2> 1239199 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10031 (-1438547450759479296)]} 0 3
[junit4:junit4] 2> 1239201 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1438547450763673600)]} 0 1
[junit4:junit4] 2> 1239202 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10032 (1438547450764722176)]} 0 1
[junit4:junit4] 2> 1239207 T3042 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 31504
[junit4:junit4] 2> 1239207 T3042 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1768880862
[junit4:junit4] 2> 1239209 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1438547450767867904)]} 0 1
[junit4:junit4] 2> 1239209 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10032 (1438547450768916480)]} 0 1
[junit4:junit4] 2> 1239209 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1438547450767867904)]} 0 5
[junit4:junit4] 2> 1239210 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10032 (1438547450768916480)]} 0 5
[junit4:junit4] 2> 1239230 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1438547450794082304)]} 0 1
[junit4:junit4] 2> 1239230 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10033 (1438547450794082305)]} 0 1
[junit4:junit4] 2> 1239238 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1438547450798276608)]} 0 1
[junit4:junit4] 2> 1239238 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10033 (1438547450799325184)]} 0 1
[junit4:junit4] 2> 1239238 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1438547450798276608)]} 0 5
[junit4:junit4] 2> 1239239 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10033 (1438547450799325184)]} 0 5
[junit4:junit4] 2> 1239340 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10034 (1438547450909425664)]} 0 1
[junit4:junit4] 2> 1239340 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1438547450909425665)]} 0 1
[junit4:junit4] 2> 1239346 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10034 (1438547450912571392)]} 0 1
[junit4:junit4] 2> 1239346 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10034 (1438547450912571392)]} 0 4
[junit4:junit4] 2> 1239348 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1438547450914668544)]} 0 1
[junit4:junit4] 2> 1239348 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1438547450914668544)]} 0 4
[junit4:junit4] 2> 1239399 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10035 (1438547450971291648)]} 0 1
[junit4:junit4] 2> 1239400 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1438547450972340224)]} 0 1
[junit4:junit4] 2> 1239406 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1438547450975485953)]} 0 1
[junit4:junit4] 2> 1239406 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1438547450975485953)]} 0 4
[junit4:junit4] 2> 1239407 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10035 (1438547450975485952)]} 0 1
[junit4:junit4] 2> 1239407 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10035 (1438547450975485952)]} 0 5
[junit4:junit4] 2> 1239433 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10036 (1438547451006943232)]} 0 1
[junit4:junit4] 2> 1239433 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1438547451006943233)]} 0 1
[junit4:junit4] 2> 1239439 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10036 (1438547451010088960)]} 0 1
[junit4:junit4] 2> 1239439 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10036 (1438547451010088960)]} 0 4
[junit4:junit4] 2> 1239441 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1438547451012186112)]} 0 1
[junit4:junit4] 2> 1239441 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1438547451012186112)]} 0 4
[junit4:junit4] 2> 1239451 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10037 (1438547451025817600)]} 0 1
[junit4:junit4] 2> 1239453 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1438547451027914752)]} 0 1
[junit4:junit4] 2> 1239457 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10037 (1438547451028963328)]} 0 1
[junit4:junit4] 2> 1239457 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10037 (1438547451028963328)]} 0 4
[junit4:junit4] 2> 1239460 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1438547451031060480)]} 0 1
[junit4:junit4] 2> 1239460 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1438547451031060480)]} 0 5
[junit4:junit4] 2> 1239559 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10037 (-1438547451140112384)]} 0 0
[junit4:junit4] 2> 1239561 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[37 (-1438547451142209536)]} 0 0
[junit4:junit4] 2> 1239564 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10037 (-1438547451143258112)]} 0 0
[junit4:junit4] 2> 1239565 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10037 (-1438547451143258112)]} 0 3
[junit4:junit4] 2> 1239567 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[37 (-1438547451146403840)]} 0 0
[junit4:junit4] 2> 1239568 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[37 (-1438547451146403840)]} 0 3
[junit4:junit4] 2> 1239570 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10038 (1438547451150598144)]} 0 1
[junit4:junit4] 2> 1239573 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1438547451153743872)]} 0 1
[junit4:junit4] 2> 1239576 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10038 (1438547451153743872)]} 0 1
[junit4:junit4] 2> 1239576 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10038 (1438547451153743872)]} 0 4
[junit4:junit4] 2> 1239579 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1438547451156889600)]} 0 1
[junit4:junit4] 2> 1239579 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1438547451156889600)]} 0 4
[junit4:junit4] 2> 1239662 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10039 (1438547451247067136)]} 0 1
[junit4:junit4] 2> 1239665 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1438547451250212864)]} 0 1
[junit4:junit4] 2> 1239668 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10039 (1438547451250212864)]} 0 1
[junit4:junit4] 2> 1239668 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10039 (1438547451250212864)]} 0 4
[junit4:junit4] 2> 1239671 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1438547451253358592)]} 0 1
[junit4:junit4] 2> 1239671 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1438547451253358592)]} 0 4
[junit4:junit4] 2> 1239690 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10040 (1438547451276427264)]} 0 1
[junit4:junit4] 2> 1239693 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1438547451279572992)]} 0 1
[junit4:junit4] 2> 1239696 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10040 (1438547451279572992)]} 0 1
[junit4:junit4] 2> 1239696 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10040 (1438547451279572992)]} 0 4
[junit4:junit4] 2> 1239700 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1438547451283767296)]} 0 1
[junit4:junit4] 2> 1239700 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1438547451283767296)]} 0 4
[junit4:junit4] 2> 1239710 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10041 (1438547451297398784)]} 0 1
[junit4:junit4] 2> 1239715 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1438547451302641664)]} 0 1
[junit4:junit4] 2> 1239716 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10041 (1438547451300544512)]} 0 1
[junit4:junit4] 2> 1239716 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10041 (1438547451300544512)]} 0 4
[junit4:junit4] 2> 1239721 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1438547451305787392)]} 0 1
[junit4:junit4] 2> 1239721 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1438547451305787392)]} 0 4
[junit4:junit4] 2> 1239801 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10042 (1438547451392819200)]} 0 1
[junit4:junit4] 2> 1239807 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10042 (1438547451395964928)]} 0 1
[junit4:junit4] 2> 1239807 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1438547451399110656)]} 0 1
[junit4:junit4] 2> 1239807 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10042 (1438547451395964928)]} 0 4
[junit4:junit4] 2> 1239814 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1438547451403304960)]} 0 1
[junit4:junit4] 2> 1239814 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1438547451403304960)]} 0 4
[junit4:junit4] 2> 1239899 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10039 (-1438547451496628224)]} 0 0
[junit4:junit4] 2> 1239904 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10039 (-1438547451499773952)]} 0 0
[junit4:junit4] 2> 1239905 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10039 (-1438547451499773952)]} 0 3
[junit4:junit4] 2> 1239906 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[39 (-1438547451503968256)]} 0 0
[junit4:junit4] 2> 1239909 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10043 (1438547451506065408)]} 0 1
[junit4:junit4] 2> 1239911 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[39 (-1438547451507113984)]} 0 0
[junit4:junit4] 2> 1239912 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[39 (-1438547451507113984)]} 0 3
[junit4:junit4] 2> 1239915 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10043 (1438547451509211136)]} 0 1
[junit4:junit4] 2> 1239915 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10043 (1438547451509211136)]} 0 4
[junit4:junit4] 2> 1239917 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1438547451514454016)]} 0 1
[junit4:junit4] 2> 1239923 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1438547451517599744)]} 0 1
[junit4:junit4] 2> 1239923 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1438547451517599744)]} 0 4
[junit4:junit4] 2> 1240000 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10041 (-1438547451602534400)]} 0 0
[junit4:junit4] 2> 1240005 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10041 (-1438547451605680128)]} 0 0
[junit4:junit4] 2> 1240006 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10041 (-1438547451605680128)]} 0 3
[junit4:junit4] 2> 1240008 T3055 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[41 (-1438547451610923008)]} 0 0
[junit4:junit4] 2> 1240010 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10044 (1438547451611971584)]} 0 1
[junit4:junit4] 2> 1240013 T3091 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[41 (-1438547451614068736)]} 0 0
[junit4:junit4] 2> 1240014 T3075 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[41 (-1438547451614068736)]} 0 3
[junit4:junit4] 2> 1240017 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10044 (1438547451616165888)]} 0 1
[junit4:junit4] 2> 1240017 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10044 (1438547451616165888)]} 0 4
[junit4:junit4] 2> 1240018 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1438547451620360192)]} 0 1
[junit4:junit4] 2> 1240024 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1438547451623505920)]} 0 1
[junit4:junit4] 2> 1240024 T3076 C530 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1438547451623505920)]} 0 4
[junit4:junit4] 2> 1240067 T3054 C529 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10045 (1438547451671740416)]} 0 1
[junit4:junit4] 2> 1240073 T3090 C528 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10045 (1438547451674886144)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C531 name=collection1 org.apache.solr.core.SolrCore@65e3ec36 url=http://127.0.0.1:10817/collection1 node=127.0.0.1:10817_ C531_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:10817_, base_url=http://127.0.0.1:10817, leader=true}
[junit4:junit4] 2> 1240073 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10045 (1438547451674886144)]} 0 4
[junit4:junit4] 2> ASYNC NEW_CORE C532 name=collection1 org.apache.solr.core.SolrCore@7e54ea77 url=http://127.0.0.1:60630/collection1 node=127.0.0.1:60630_ C532_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:60630_, base_url=http://127.0.0.1:60630, leader=true}
[junit4:junit4] 2> 1240090 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1438547451679080448)]} 0 17
[junit4:junit4] 2> ASYNC NEW_CORE C533 name=collection1 org.apache.solr.core.SolrCore@55a6d031 url=http://127.0.0.1:31504/collection1 node=127.0.0.1:31504_ C533_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:31504_, base_url=http://127.0.0.1:31504}
[junit4:junit4] 2> 1240097 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1438547451700051968)]} 0 1
[junit4:junit4] 2> 1240097 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1438547451700051968)]} 0 4
[junit4:junit4] 2> 1240112 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10043 (-1438547451719974912)]} 0 0
[junit4:junit4] 2> 1240118 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10043 (-1438547451723120640)]} 0 0
[junit4:junit4] 2> 1240119 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10043 (-1438547451723120640)]} 0 4
[junit4:junit4] 2> 1240120 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[43 (-1438547451728363520)]} 0 0
[junit4:junit4] 2> 1240123 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10046 (1438547451730460672)]} 0 1
[junit4:junit4] 2> 1240125 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[43 (-1438547451731509248)]} 0 0
[junit4:junit4] 2> 1240126 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[43 (-1438547451731509248)]} 0 3
[junit4:junit4] 2> 1240129 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10046 (1438547451733606400)]} 0 1
[junit4:junit4] 2> 1240129 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10046 (1438547451733606400)]} 0 4
[junit4:junit4] 2> 1240130 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1438547451737800704)]} 0 1
[junit4:junit4] 2> 1240137 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1438547451740946432)]} 0 1
[junit4:junit4] 2> 1240137 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1438547451740946432)]} 0 5
[junit4:junit4] 2> 1240192 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10047 (1438547451802812416)]} 0 1
[junit4:junit4] 2> 1240198 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10047 (1438547451805958144)]} 0 1
[junit4:junit4] 2> 1240198 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10047 (1438547451805958144)]} 0 4
[junit4:junit4] 2> 1240199 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1438547451810152448)]} 0 1
[junit4:junit4] 2> 1240205 T3090 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:10817/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1438547451813298176)]} 0 1
[junit4:junit4] 2> 1240205 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1438547451813298176)]} 0 4
[junit4:junit4] 2> 1240209 T3103 C533 P31504 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:10817/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1240209 T3103 C533 P31504 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:31504 START replicas=[http://127.0.0.1:10817/collection1/] nUpdates=100
[junit4:junit4] 2> 1240210 T3103 C533 P31504 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1240210 T3103 C533 P31504 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1240210 T3103 C533 P31504 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1240211 T3103 C533 P31504 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1240211 T3103 C533 P31504 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/tlog/tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 1240211 T3103 C533 P31504 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:10817/collection1/. core=collection1
[junit4:junit4] 2> 1240211 T3077 C531 P10817 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> 1240211 T3103 C533 P31504 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1240223 T3078 C531 P10817 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1240238 T3078 C531 P10817 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38c9d6b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237d7328),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@38c9d6b2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@237d7328),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1240238 T3078 C531 P10817 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1240241 T3078 C531 P10817 oass.SolrIndexSearcher.<init> Opening Searcher@46768b7b realtime
[junit4:junit4] 2> 1240241 T3065 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1240241 T3078 C531 P10817 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1240242 T3078 C531 P10817 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 19
[junit4:junit4] 2> 1240242 T3065 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:31504__collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:31504_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31504"}
[junit4:junit4] 2> 1240243 T3103 C533 P31504 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1240243 T3103 C533 P31504 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1240246 T3079 C531 P10817 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1240246 T3079 C531 P10817 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1240247 T3103 C533 P31504 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1240247 T3103 C533 P31504 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1240247 T3103 C533 P31504 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1240249 T3079 C531 P10817 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> 1240250 T3103 C533 P31504 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 5
[junit4:junit4] 2> 1240251 T3103 C533 P31504 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index.20130622085557775
[junit4:junit4] 2> 1240251 T3103 C533 P31504 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1c409af9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@183aa7d0) fullCopy=false
[junit4:junit4] 2> 1240254 T3079 C531 P10817 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=_0.cfs&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1240258 T3100 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> 1240258 T3079 C531 P10817 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=_0.cfe&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1240258 T3064 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> 1240258 T3071 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> 1240258 T3084 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> 1240262 T3079 C531 P10817 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> 1240265 T3079 C531 P10817 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1240268 T3079 C531 P10817 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> C533_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:31504_, base_url=http://127.0.0.1:31504}
[junit4:junit4] 2> 1240269 T3103 C533 P31504 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1240270 T3103 C533 P31504 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1240270 T3103 C533 P31504 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1240270 T3103 C533 P31504 oasu.DefaultSolrCoreState.newIndexWriter Closing old IndexWriter... core=collection1
[junit4:junit4] 2> 1240285 T3103 C533 P31504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1240285 T3103 C533 P31504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1240289 T3103 C533 P31504 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1240289 T3103 C533 P31504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1240289 T3103 C533 P31504 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1240291 T3103 C533 P31504 oass.SolrIndexSearcher.<init> Opening Searcher@7945a4e2 main
[junit4:junit4] 2> 1240292 T3102 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7945a4e2 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c94/38)}
[junit4:junit4] 2> 1240293 T3103 C533 P31504 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index.20130622085557775 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index.20130622085557775;done=true>>]
[junit4:junit4] 2> 1240293 T3103 C533 P31504 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index.20130622085557775
[junit4:junit4] 2> 1240294 T3103 C533 P31504 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index.20130622085557775
[junit4:junit4] 2> 1240300 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10048 (1438547451916058624)]} 0 1
[junit4:junit4] 2> 1240301 T3103 C533 P31504 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 1240301 T3111 C533 P31504 oasu.UpdateLog$LogReplayer.doReplay WARN Starting log replay tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/tlog/tlog.0000000000000000000 refcount=2} active=true starting pos=10471
[junit4:junit4] 2> 1240305 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10048 (1438547451920252928)]} 0 2
[junit4:junit4] 2> 1240307 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1438547451923398656)]} 0 1
[junit4:junit4] 2> 1240307 T3111 C533 P31504 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1240308 T3111 C533 P31504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7376134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@54e038e6),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1240309 T3111 C533 P31504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1240309 T3111 C533 P31504 oass.SolrIndexSearcher.<init> Opening Searcher@3875c394 main
[junit4:junit4] 2> 1240310 T3111 C533 P31504 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1240310 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1438547451926544384)]} 0 1
[junit4:junit4] 2> 1240310 T3102 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3875c394 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c94/38)}
[junit4:junit4] 2> 1240311 T3111 C533 P31504 oasup.LogUpdateProcessor.finish [collection1] {} 0 10
[junit4:junit4] 2> 1240311 T3111 C533 P31504 oasu.UpdateLog$LogReplayer.run WARN Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=10471}
[junit4:junit4] 2> 1240312 T3103 C533 P31504 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1240312 T3103 C533 P31504 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1240312 T3103 C533 P31504 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1240314 T3103 C533 P31504 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1240334 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10044 (-1438547451952758784)]} 0 0
[junit4:junit4] 2> 1240337 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10044 (-1438547451955904512)]} 0 0
[junit4:junit4] 2> 1240339 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[44 (-1438547451958001664)]} 0 0
[junit4:junit4] 2> 1240341 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10049 (1438547451959050240)]} 0 1
[junit4:junit4] 2> 1240342 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[44 (-1438547451961147392)]} 0 0
[junit4:junit4] 2> 1240344 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10049 (1438547451962195968)]} 0 1
[junit4:junit4] 2> 1240346 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1438547451964293120)]} 0 1
[junit4:junit4] 2> 1240349 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1438547451967438848)]} 0 1
[junit4:junit4] 2> 1240417 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10045 (-1438547452039790592)]} 0 0
[junit4:junit4] 2> 1240420 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10045 (-1438547452042936320)]} 0 0
[junit4:junit4] 2> 1240422 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[45 (-1438547452045033472)]} 0 0
[junit4:junit4] 2> 1240424 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10050 (1438547452046082048)]} 0 1
[junit4:junit4] 2> 1240425 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[45 (-1438547452048179200)]} 0 0
[junit4:junit4] 2> 1240427 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10050 (1438547452049227776)]} 0 1
[junit4:junit4] 2> 1240430 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1438547452052373504)]} 0 1
[junit4:junit4] 2> 1240433 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1438547452055519232)]} 0 1
[junit4:junit4] 2> 1240497 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10046 (-1438547452123676672)]} 0 0
[junit4:junit4] 2> 1240500 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10046 (-1438547452126822400)]} 0 0
[junit4:junit4] 2> 1240503 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[46 (-1438547452129968129)]} 0 0
[junit4:junit4] 2> 1240504 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10051 (1438547452129968128)]} 0 1
[junit4:junit4] 2> 1240506 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[46 (-1438547452133113856)]} 0 0
[junit4:junit4] 2> 1240507 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10051 (1438547452133113857)]} 0 1
[junit4:junit4] 2> 1240510 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1438547452136259584)]} 0 1
[junit4:junit4] 2> 1240514 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1438547452140453888)]} 0 1
[junit4:junit4] 2> 1240587 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10052 (1438547452216999936)]} 0 1
[junit4:junit4] 2> 1240590 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10052 (1438547452220145664)]} 0 1
[junit4:junit4] 2> 1240594 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1438547452224339968)]} 0 1
[junit4:junit4] 2> 1240598 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1438547452228534272)]} 0 1
[junit4:junit4] 2> 1240615 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10047 (-1438547452247408640)]} 0 0
[junit4:junit4] 2> 1240618 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10047 (-1438547452250554368)]} 0 0
[junit4:junit4] 2> 1240622 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[47 (-1438547452254748672)]} 0 0
[junit4:junit4] 2> 1240623 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10053 (1438547452254748673)]} 0 1
[junit4:junit4] 2> 1240625 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[47 (-1438547452257894401)]} 0 0
[junit4:junit4] 2> 1240626 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10053 (1438547452257894400)]} 0 1
[junit4:junit4] 2> 1240630 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1438547452262088704)]} 0 1
[junit4:junit4] 2> 1240633 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1438547452265234432)]} 0 1
[junit4:junit4] 2> 1240650 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10049 (-1438547452284108800)]} 0 0
[junit4:junit4] 2> 1240653 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10049 (-1438547452287254528)]} 0 0
[junit4:junit4] 2> 1240657 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10054 (1438547452290400256)]} 0 1
[junit4:junit4] 2> 1240658 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[49 (-1438547452292497408)]} 0 0
[junit4:junit4] 2> 1240660 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10054 (1438547452293545984)]} 0 1
[junit4:junit4] 2> 1240661 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[49 (-1438547452295643136)]} 0 0
[junit4:junit4] 2> 1240665 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1438547452298788864)]} 0 1
[junit4:junit4] 2> 1240669 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1438547452302983168)]} 0 1
[junit4:junit4] 2> 1240707 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10055 (1438547452342829056)]} 0 1
[junit4:junit4] 2> 1240711 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10055 (1438547452347023360)]} 0 1
[junit4:junit4] 2> 1240715 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1438547452351217664)]} 0 1
[junit4:junit4] 2> 1240718 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1438547452354363392)]} 0 1
[junit4:junit4] 2> 1240764 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10056 (1438547452402597888)]} 0 1
[junit4:junit4] 2> 1240767 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10056 (1438547452405743616)]} 0 1
[junit4:junit4] 2> 1240771 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1438547452409937920)]} 0 1
[junit4:junit4] 2> 1240775 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1438547452414132224)]} 0 1
[junit4:junit4] 2> 1240795 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10050 (-1438547452436152320)]} 0 0
[junit4:junit4] 2> 1240798 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10050 (-1438547452439298048)]} 0 0
[junit4:junit4] 2> 1240803 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10057 (1438547452443492352)]} 0 1
[junit4:junit4] 2> 1240805 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[50 (-1438547452446638080)]} 0 0
[junit4:junit4] 2> 1240806 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10057 (1438547452446638080)]} 0 1
[junit4:junit4] 2> 1240809 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[50 (-1438547452450832384)]} 0 0
[junit4:junit4] 2> 1240813 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1438547452453978112)]} 0 1
[junit4:junit4] 2> 1240816 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1438547452457123840)]} 0 1
[junit4:junit4] 2> 1240863 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10053 (-1438547452507455488)]} 0 0
[junit4:junit4] 2> 1240866 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10053 (-1438547452510601216)]} 0 0
[junit4:junit4] 2> 1240870 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10058 (1438547452513746944)]} 0 1
[junit4:junit4] 2> 1240872 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[53 (-1438547452516892672)]} 0 0
[junit4:junit4] 2> 1240873 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10058 (1438547452516892672)]} 0 1
[junit4:junit4] 2> 1240875 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10054 (-1438547452520038400)]} 0 0
[junit4:junit4] 2> 1240875 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[53 (-1438547452520038400)]} 0 0
[junit4:junit4] 2> 1240878 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10054 (-1438547452523184128)]} 0 0
[junit4:junit4] 2> 1240879 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1438547452523184128)]} 0 1
[junit4:junit4] 2> 1240883 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1438547452527378432)]} 0 1
[junit4:junit4] 2> 1240883 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10059 (1438547452527378432)]} 0 1
[junit4:junit4] 2> 1240885 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[54 (-1438547452530524160)]} 0 0
[junit4:junit4] 2> 1240887 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10059 (1438547452531572736)]} 0 1
[junit4:junit4] 2> 1240889 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[54 (-1438547452534718464)]} 0 0
[junit4:junit4] 2> 1240894 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1438547452538912768)]} 0 1
[junit4:junit4] 2> 1240897 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1438547452542058496)]} 0 1
[junit4:junit4] 2> 1240916 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10058 (-1438547452563030016)]} 0 0
[junit4:junit4] 2> 1240920 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10058 (-1438547452567224320)]} 0 0
[junit4:junit4] 2> 1240924 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10060 (1438547452570370048)]} 0 1
[junit4:junit4] 2> 1240926 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[58 (-1438547452573515776)]} 0 0
[junit4:junit4] 2> 1240928 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10060 (1438547452574564352)]} 0 1
[junit4:junit4] 2> 1240929 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[58 (-1438547452576661504)]} 0 0
[junit4:junit4] 2> 1240933 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1438547452579807232)]} 0 1
[junit4:junit4] 2> 1240936 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1438547452582952960)]} 0 1
[junit4:junit4] 2> 1240981 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10061 (1438547452630138880)]} 0 1
[junit4:junit4] 2> 1240985 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10061 (1438547452634333184)]} 0 1
[junit4:junit4] 2> 1240989 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1438547452638527488)]} 0 1
[junit4:junit4] 2> 1240992 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1438547452641673216)]} 0 1
[junit4:junit4] 2> 1241054 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10062 (1438547452706684928)]} 0 1
[junit4:junit4] 2> 1241057 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10062 (1438547452709830656)]} 0 1
[junit4:junit4] 2> 1241060 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1438547452712976384)]} 0 1
[junit4:junit4] 2> 1241063 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1438547452716122112)]} 0 1
[junit4:junit4] 2> 1241149 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10063 (1438547452806299648)]} 0 1
[junit4:junit4] 2> 1241152 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10063 (1438547452809445376)]} 0 1
[junit4:junit4] 2> 1241156 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1438547452813639680)]} 0 1
[junit4:junit4] 2> 1241160 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1438547452817833984)]} 0 1
[junit4:junit4] 2> 1241177 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10064 (1438547452835659776)]} 0 1
[junit4:junit4] 2> 1241180 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10064 (1438547452838805504)]} 0 1
[junit4:junit4] 2> 1241185 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1438547452844048384)]} 0 1
[junit4:junit4] 2> 1241188 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1438547452847194112)]} 0 1
[junit4:junit4] 2> 1241275 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10063 (-1438547452939468800)]} 0 0
[junit4:junit4] 2> 1241278 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10063 (-1438547452942614528)]} 0 0
[junit4:junit4] 2> 1241282 T3054 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10065 (1438547452945760256)]} 0 1
[junit4:junit4] 2> 1241283 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[63 (-1438547452947857408)]} 0 0
[junit4:junit4] 2> 1241285 T3075 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10065 (1438547452948905984)]} 0 1
[junit4:junit4] 2> 1241286 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[63 (-1438547452951003136)]} 0 0
[junit4:junit4] 2> 1241290 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1438547452954148864)]} 0 1
[junit4:junit4] 2> 1241293 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1438547452957294592)]} 0 1
[junit4:junit4] 2> 1241380 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10066 (1438547453048520704)]} 0 1
[junit4:junit4] 2> 1241384 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10066 (1438547453052715008)]} 0 1
[junit4:junit4] 2> 1241390 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1438547453059006464)]} 0 1
[junit4:junit4] 2> 1241393 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1438547453062152192)]} 0 1
[junit4:junit4] 2> 1241405 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10067 (1438547453074735104)]} 0 1
[junit4:junit4] 2> 1241408 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10067 (1438547453077880832)]} 0 1
[junit4:junit4] 2> 1241413 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1438547453083123712)]} 0 1
[junit4:junit4] 2> 1241416 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1438547453086269440)]} 0 1
[junit4:junit4] 2> 1241503 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10065 (-1438547453178544128)]} 0 0
[junit4:junit4] 2> 1241506 T3076 C531 P10817 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10065 (-1438547453181689856)]} 0 0
[junit4:junit4] 2> 1241510 T3055 C532 P60630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10068 (1438547453184835584)]} 0 1
[junit4:junit4] 2> 1241512 T3054 C532 P60630
[...truncated too long message...]
cStrategy.syncToMe http://127.0.0.1:31504/collection1/ has no replicas
[junit4:junit4] 2> 1337607 T3124 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:31504/collection1/
[junit4:junit4] 2> 1337607 T3124 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1337609 T3136 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:10817__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[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:10817_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10817"}
[junit4:junit4] 2> 1337624 T3124 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 1337624 T3124 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> 1337625 T3124 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> 1337634 T3042 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 31504
[junit4:junit4] 2> 1337634 T3042 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1685972303
[junit4:junit4] 2> 1338636 T3042 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1338636 T3042 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1338643 T3042 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@6ae13d5e
[junit4:junit4] 2> 1338650 T3042 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=43,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=44,cumulative_deletesById=22,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 1338651 T3042 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1338651 T3042 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1338652 T3042 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1338654 T3042 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1338655 T3042 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1338655 T3042 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index;done=false>>]
[junit4:junit4] 2> 1338656 T3042 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2/index
[junit4:junit4] 2> 1338656 T3042 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2;done=false>>]
[junit4:junit4] 2> 1338656 T3042 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371905739795/jetty2
[junit4:junit4] 2> 1338658 T3136 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89909214563729418-127.0.0.1:31504_-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 1338659 T3042 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 1338725 T3042 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1338727 T3042 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:26370 26370
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.method=testDistribSearch -Dtests.seed=20A86B6850A159DE -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=de_LU -Dtests.timezone=America/Iqaluit -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 117s J0 | RecoveryZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: expected:<230> but was:<42>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([20A86B6850A159DE:A14EE57027FE39E2]:0)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1338919 T3042 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 116659 T3041 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 1339959 T3124 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1339959 T3124 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> 1339959 T3124 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=MockVariableIntBlock(baseBlockSize=43), text=MockFixedIntBlock(blockSize=1694), _version_=MockVariableIntBlock(baseBlockSize=43), rnd_b=PostingsFormat(name=MockRandom), intDefault=MockVariableIntBlock(baseBlockSize=43), timestamp=MockVariableIntBlock(baseBlockSize=43), id=PostingsFormat(name=MockRandom), a_t=MockVariableIntBlock(baseBlockSize=43), range_facet_sl=MockFixedIntBlock(blockSize=1694), range_facet_si=PostingsFormat(name=Direct), other_tl1=MockVariableIntBlock(baseBlockSize=43), multiDefault=PostingsFormat(name=Direct), a_si=PostingsFormat(name=Direct)}, docValues:{timestamp=DocValuesFormat(name=Asserting)}, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=de_LU, timezone=America/Iqaluit
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=202514144,total=378535936
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestDocSet, PeerSyncTest, DocumentBuilderTest, TermVectorComponentTest, TestStressVersions, MBeansHandlerTest, TestSolrIndexConfig, QueryParsingTest, QueryElevationComponentTest, TestPluginEnable, QueryEqualityTest, TestRemoteStreaming, TestSort, TestExtendedDismaxParser, ChaosMonkeyNothingIsSafeTest, TestFunctionQuery, ZkControllerTest, DirectSolrConnectionTest, ScriptEngineTest, SchemaVersionSpecificBehaviorTest, AlternateDirectoryTest, TestSchemaSimilarityResource, SynonymTokenizerTest, TestRealTimeGet, PreAnalyzedFieldTest, TestRandomDVFaceting, BinaryUpdateRequestHandlerTest, TestPHPSerializedResponseWriter, TestReversedWildcardFilterFactory, TestCloudManagedSchemaAddField, SliceStateUpdateTest, RegexBoostProcessorTest, MinimalSchemaTest, FileBasedSpellCheckerTest, MoreLikeThisHandlerTest, QueryResultKeyTest, TestLFUCache, SOLR749Test, TestTrie, OverseerTest, BadCopyFieldTest, TestStressRecovery, WordBreakSolrSpellCheckerTest, TestSearchPerf, BadComponentTest, DistributedQueryElevationComponentTest, TestSurroundQueryParser, TestSolrXmlPersistence, DocValuesTest, CircularListTest, SyncSliceTest, TestWriterPerf, DistributedTermsComponentTest, TestFieldCollectionResource, ShardRoutingTest, TestClassNameShortening, TestManagedSchema, TestCoreContainer, UUIDFieldTest, TestUniqueKeyFieldResource, TestPropInjectDefaults, TestQueryUtils, SimpleFacetsTest, TestSolrQueryParser, StatelessScriptUpdateProcessorFactoryTest, TestFaceting, ExternalFileFieldSortTest, SpatialFilterTest, TestReplicationHandler, UpdateRequestProcessorFactoryTest, LeaderElectionIntegrationTest, RecoveryZkTest]
[junit4:junit4] Completed on J0 in 117.95s, 1 test, 1 failure <<< FAILURES!
[...truncated 440 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:366: 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:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 53 minutes 3 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure