You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/14 08:12:03 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_21) - Build #
6127 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6127/
Java: 32bit/jdk1.7.0_21 -server -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.RecoveryZkTest.testDistribSearch
Error Message:
expected:<250> but was:<54>
Stack Trace:
java.lang.AssertionError: expected:<250> but was:<54>
at __randomizedtesting.SeedInfo.seed([366A568BB4C93CB7:B78CD893C3965C8B]: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:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9611 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 675843 T2401 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 675846 T2401 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-RecoveryZkTest-1371189824144
[junit4:junit4] 2> 675846 T2401 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 675847 T2402 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 675947 T2401 oasc.ZkTestServer.run start zk server on port:54410
[junit4:junit4] 2> 675948 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 675952 T2408 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d05c51 name:ZooKeeperConnection Watcher:127.0.0.1:54410 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 675952 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 675953 T2401 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 675957 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 675958 T2410 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@576878 name:ZooKeeperConnection Watcher:127.0.0.1:54410/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 675958 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 675959 T2401 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 675961 T2401 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 675963 T2401 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 675964 T2401 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 675966 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 675966 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 675969 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 675970 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 675972 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 675972 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 675974 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 675975 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 675976 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 675977 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 675978 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 675979 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 675980 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 675981 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 675983 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 675983 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 675985 T2401 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 675985 T2401 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 676047 T2401 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 676050 T2401 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40648
[junit4:junit4] 2> 676051 T2401 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 676051 T2401 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 676052 T2401 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285
[junit4:junit4] 2> 676052 T2401 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/solr.xml
[junit4:junit4] 2> 676052 T2401 oasc.CoreContainer.<init> New CoreContainer 16754721
[junit4:junit4] 2> 676053 T2401 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/'
[junit4:junit4] 2> 676053 T2401 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/'
[junit4:junit4] 2> 676091 T2401 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 676092 T2401 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 676092 T2401 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 676092 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 676093 T2401 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 676093 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 676093 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 676094 T2401 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 676094 T2401 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 676094 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 676097 T2401 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 676097 T2401 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54410/solr
[junit4:junit4] 2> 676098 T2401 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 676098 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 676101 T2421 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a0ee21 name:ZooKeeperConnection Watcher:127.0.0.1:54410 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 676101 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 676103 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 676105 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 676107 T2423 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8f3266 name:ZooKeeperConnection Watcher:127.0.0.1:54410/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 676107 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 676109 T2401 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 676111 T2401 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 676113 T2401 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 676114 T2401 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40648_
[junit4:junit4] 2> 676115 T2401 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40648_
[junit4:junit4] 2> 676117 T2401 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 676121 T2401 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 676122 T2401 oasc.Overseer.start Overseer (id=89862296315297795-127.0.0.1:40648_-n_0000000000) starting
[junit4:junit4] 2> 676125 T2401 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 676128 T2425 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 676128 T2401 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 676130 T2401 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 676131 T2401 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 676132 T2424 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 676135 T2426 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 676135 T2426 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 677635 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 677636 T2424 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:40648_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40648"}
[junit4:junit4] 2> 677636 T2424 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 677636 T2424 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 677639 T2423 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> 678136 T2426 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/collection1
[junit4:junit4] 2> 678136 T2426 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 678137 T2426 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 678137 T2426 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 678138 T2426 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/collection1/'
[junit4:junit4] 2> 678139 T2426 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/collection1/lib/README' to classloader
[junit4:junit4] 2> 678139 T2426 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 678173 T2426 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 678202 T2426 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 678203 T2426 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 678206 T2426 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 678492 T2426 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 678501 T2426 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 678503 T2426 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 678512 T2426 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 678514 T2426 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 678516 T2426 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 678517 T2426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 678517 T2426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 678518 T2426 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 678518 T2426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 678518 T2426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 678518 T2426 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 678519 T2426 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1371189824285/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/control/data/
[junit4:junit4] 2> 678519 T2426 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@79b12a
[junit4:junit4] 2> 678519 T2426 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 678520 T2426 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/control/data
[junit4:junit4] 2> 678520 T2426 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/control/data/index/
[junit4:junit4] 2> 678520 T2426 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1371189824144/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 678520 T2426 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/control/data/index
[junit4:junit4] 2> 678521 T2426 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18e8c40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@253526),segFN=segments_1,generation=1}
[junit4:junit4] 2> 678522 T2426 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 678523 T2426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 678523 T2426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 678524 T2426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 678524 T2426 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 678524 T2426 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 678524 T2426 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 678525 T2426 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 678525 T2426 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 678525 T2426 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 678527 T2426 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 678529 T2426 oass.SolrIndexSearcher.<init> Opening Searcher@3e08d6 main
[junit4:junit4] 2> 678530 T2426 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/control/data/tlog
[junit4:junit4] 2> 678530 T2426 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 678530 T2426 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 678533 T2427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3e08d6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 678534 T2426 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 678534 T2426 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40648 collection:control_collection shard:shard1
[junit4:junit4] 2> 678534 T2426 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 678539 T2426 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 678540 T2426 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 678541 T2426 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 678541 T2426 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40648/collection1/
[junit4:junit4] 2> 678541 T2426 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 678541 T2426 oasc.SyncStrategy.syncToMe http://127.0.0.1:40648/collection1/ has no replicas
[junit4:junit4] 2> 678541 T2426 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40648/collection1/
[junit4:junit4] 2> 678541 T2426 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 679142 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 679148 T2423 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> 679196 T2426 oasc.ZkController.register We are http://127.0.0.1:40648/collection1/ and leader is http://127.0.0.1:40648/collection1/
[junit4:junit4] 2> 679196 T2426 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40648
[junit4:junit4] 2> 679197 T2426 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 679197 T2426 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 679197 T2426 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 679198 T2426 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 679199 T2401 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 679200 T2401 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 679200 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 679204 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 679206 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 679207 T2430 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@110ef6 name:ZooKeeperConnection Watcher:127.0.0.1:54410/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 679207 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 679209 T2401 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 679211 T2401 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 679271 T2401 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 679274 T2401 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48496
[junit4:junit4] 2> 679274 T2401 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 679274 T2401 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 679275 T2401 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509
[junit4:junit4] 2> 679275 T2401 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/solr.xml
[junit4:junit4] 2> 679275 T2401 oasc.CoreContainer.<init> New CoreContainer 18553941
[junit4:junit4] 2> 679276 T2401 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/'
[junit4:junit4] 2> 679276 T2401 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/'
[junit4:junit4] 2> 679313 T2401 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 679313 T2401 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 679314 T2401 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 679314 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 679314 T2401 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 679315 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 679315 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 679315 T2401 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 679316 T2401 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 679316 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 679319 T2401 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 679319 T2401 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54410/solr
[junit4:junit4] 2> 679319 T2401 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 679320 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 679322 T2441 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@92536b name:ZooKeeperConnection Watcher:127.0.0.1:54410 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 679322 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 679324 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 679327 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 679328 T2443 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9be06d name:ZooKeeperConnection Watcher:127.0.0.1:54410/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 679328 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 679331 T2401 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 680333 T2401 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48496_
[junit4:junit4] 2> 680335 T2401 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48496_
[junit4:junit4] 2> 680337 T2423 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 680337 T2430 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 680338 T2423 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> 680337 T2443 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 680341 T2444 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 680342 T2444 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 680652 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 680653 T2424 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40648__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:40648_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40648"}
[junit4:junit4] 2> 680655 T2424 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:48496_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48496"}
[junit4:junit4] 2> 680656 T2424 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 680656 T2424 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 680659 T2443 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> 680659 T2423 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> 680659 T2430 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> 681343 T2444 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/collection1
[junit4:junit4] 2> 681343 T2444 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 681344 T2444 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 681344 T2444 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 681345 T2444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/collection1/'
[junit4:junit4] 2> 681345 T2444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/collection1/lib/README' to classloader
[junit4:junit4] 2> 681345 T2444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 681367 T2444 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 681394 T2444 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 681395 T2444 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 681399 T2444 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 681684 T2444 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 681688 T2444 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 681691 T2444 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 681699 T2444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 681701 T2444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 681704 T2444 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 681704 T2444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 681705 T2444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 681705 T2444 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 681706 T2444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 681706 T2444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 681706 T2444 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 681706 T2444 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1371189827509/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty1/
[junit4:junit4] 2> 681706 T2444 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@79b12a
[junit4:junit4] 2> 681707 T2444 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 681707 T2444 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty1
[junit4:junit4] 2> 681707 T2444 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty1/index/
[junit4:junit4] 2> 681707 T2444 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 681708 T2444 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty1/index
[junit4:junit4] 2> 681709 T2444 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b1f41a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 681709 T2444 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 681710 T2444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 681711 T2444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 681711 T2444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 681712 T2444 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 681712 T2444 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 681712 T2444 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 681712 T2444 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 681713 T2444 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 681713 T2444 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 681715 T2444 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 681717 T2444 oass.SolrIndexSearcher.<init> Opening Searcher@13f7db3 main
[junit4:junit4] 2> 681717 T2444 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty1/tlog
[junit4:junit4] 2> 681718 T2444 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 681718 T2444 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 681721 T2445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13f7db3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 681722 T2444 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 681722 T2444 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48496 collection:collection1 shard:shard1
[junit4:junit4] 2> 681723 T2444 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 681727 T2444 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 681729 T2444 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 681729 T2444 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 681729 T2444 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48496/collection1/
[junit4:junit4] 2> 681729 T2444 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 681729 T2444 oasc.SyncStrategy.syncToMe http://127.0.0.1:48496/collection1/ has no replicas
[junit4:junit4] 2> 681729 T2444 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48496/collection1/
[junit4:junit4] 2> 681729 T2444 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 682163 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 682168 T2423 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> 682168 T2430 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> 682168 T2443 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> 682184 T2444 oasc.ZkController.register We are http://127.0.0.1:48496/collection1/ and leader is http://127.0.0.1:48496/collection1/
[junit4:junit4] 2> 682184 T2444 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48496
[junit4:junit4] 2> 682184 T2444 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 682185 T2444 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 682185 T2444 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 682186 T2444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 682187 T2401 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 682188 T2401 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 682188 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 682248 T2401 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 682250 T2401 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39004
[junit4:junit4] 2> 682250 T2401 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 682250 T2401 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 682251 T2401 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489
[junit4:junit4] 2> 682251 T2401 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/solr.xml
[junit4:junit4] 2> 682251 T2401 oasc.CoreContainer.<init> New CoreContainer 14565505
[junit4:junit4] 2> 682252 T2401 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/'
[junit4:junit4] 2> 682252 T2401 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/'
[junit4:junit4] 2> 682289 T2401 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 682289 T2401 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 682290 T2401 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 682290 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 682290 T2401 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 682291 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 682291 T2401 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 682291 T2401 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 682291 T2401 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 682292 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 682294 T2401 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 682295 T2401 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54410/solr
[junit4:junit4] 2> 682295 T2401 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 682296 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 682298 T2457 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@124f7ae name:ZooKeeperConnection Watcher:127.0.0.1:54410 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 682299 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 682301 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 682303 T2401 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 682304 T2459 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@777b4b name:ZooKeeperConnection Watcher:127.0.0.1:54410/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 682304 T2401 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 682307 T2401 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 683309 T2401 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39004_
[junit4:junit4] 2> 683311 T2401 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39004_
[junit4:junit4] 2> 683316 T2430 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> 683317 T2443 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 683317 T2459 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 683317 T2443 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> 683317 T2423 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 683317 T2423 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> 683318 T2430 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 683321 T2460 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 683321 T2460 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 683671 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 683672 T2424 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:48496__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:48496_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48496"}
[junit4:junit4] 2> 683674 T2424 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:39004_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39004"}
[junit4:junit4] 2> 683675 T2424 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 683675 T2424 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 683678 T2443 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> 683678 T2423 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> 683678 T2430 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> 683678 T2459 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> 684322 T2460 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/collection1
[junit4:junit4] 2> 684323 T2460 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 684324 T2460 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 684324 T2460 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 684326 T2460 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/collection1/'
[junit4:junit4] 2> 684327 T2460 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/collection1/lib/README' to classloader
[junit4:junit4] 2> 684328 T2460 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 684375 T2460 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 684401 T2460 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 684402 T2460 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 684405 T2460 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 684708 T2460 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 684712 T2460 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 684715 T2460 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 684724 T2460 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 684727 T2460 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 684729 T2460 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 684730 T2460 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 684730 T2460 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 684731 T2460 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 684731 T2460 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 684732 T2460 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 684732 T2460 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 684732 T2460 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1371189830489/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/
[junit4:junit4] 2> 684732 T2460 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@79b12a
[junit4:junit4] 2> 684732 T2460 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 684733 T2460 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2
[junit4:junit4] 2> 684733 T2460 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index/
[junit4:junit4] 2> 684733 T2460 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 684734 T2460 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index
[junit4:junit4] 2> 684735 T2460 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 684735 T2460 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 684736 T2460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 684737 T2460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 684737 T2460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 684737 T2460 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 684738 T2460 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 684738 T2460 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 684738 T2460 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 684738 T2460 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 684739 T2460 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 684741 T2460 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 684743 T2460 oass.SolrIndexSearcher.<init> Opening Searcher@1131279 main
[junit4:junit4] 2> 684743 T2460 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/tlog
[junit4:junit4] 2> 684744 T2460 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 684744 T2460 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 684747 T2461 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1131279 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 684748 T2460 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 684748 T2460 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39004 collection:collection1 shard:shard1
[junit4:junit4] 2> 684764 T2460 oasc.ZkController.register We are http://127.0.0.1:39004/collection1/ and leader is http://127.0.0.1:48496/collection1/
[junit4:junit4] 2> 684764 T2460 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39004
[junit4:junit4] 2> 684765 T2460 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 684765 T2460 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2143 name=collection1 org.apache.solr.core.SolrCore@dc76dd url=http://127.0.0.1:39004/collection1 node=127.0.0.1:39004_ C2143_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:39004_, base_url=http://127.0.0.1:39004}
[junit4:junit4] 2> 684765 T2462 C2143 P39004 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 684766 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 684766 T2460 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 684766 T2462 C2143 P39004 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 684766 T2462 C2143 P39004 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 684767 T2401 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 684767 T2401 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 684767 T2401 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 684768 T2462 C2143 P39004 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 684770 T2401 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 684771 T2436 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:39004__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C2144 name=collection1 org.apache.solr.core.SolrCore@38f5d url=http://127.0.0.1:40648/collection1 node=127.0.0.1:40648_ C2144_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:40648_, base_url=http://127.0.0.1:40648, leader=true}
[junit4:junit4] 2> 684777 T2418 C2144 P40648 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18e8c40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@253526),segFN=segments_1,generation=1}
[junit4:junit4] 2> 684778 T2418 C2144 P40648 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 684779 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1437796750405402624)]} 0 3
[junit4:junit4] 2> 684779 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10001 (1437796750405402625)]} 0 3
[junit4:junit4] 2> ASYNC NEW_CORE C2145 name=collection1 org.apache.solr.core.SolrCore@8fb3bd url=http://127.0.0.1:48496/collection1 node=127.0.0.1:48496_ C2145_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:48496_, base_url=http://127.0.0.1:48496, leader=true}
[junit4:junit4] 2> 684787 T2439 C2145 P48496 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b1f41a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 684787 T2439 C2145 P48496 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 684788 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1437796750415888384)]} 0 2
[junit4:junit4] 2> 684788 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10001 (1437796750417985536)]} 0 1
[junit4:junit4] 2> 684806 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10002 (1437796750435811329)]} 0 1
[junit4:junit4] 2> 684806 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437796750435811328)]} 0 1
[junit4:junit4] 2> 684808 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10002 (1437796750437908480)]} 0 1
[junit4:junit4] 2> 684808 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437796750438957056)]} 0 0
[junit4:junit4] 2> 684826 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10003 (1437796750457831424)]} 0 0
[junit4:junit4] 2> 684826 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437796750457831425)]} 0 0
[junit4:junit4] 2> 684828 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10003 (1437796750459928576)]} 0 0
[junit4:junit4] 2> 684828 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437796750459928577)]} 0 0
[junit4:junit4] 2> 684862 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1437796750494531584)]} 0 1
[junit4:junit4] 2> 684862 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10004 (1437796750494531585)]} 0 1
[junit4:junit4] 2> 684864 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1437796750497677312)]} 0 0
[junit4:junit4] 2> 684864 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10004 (1437796750497677313)]} 0 0
[junit4:junit4] 2> 684961 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[2 (-1437796750598340608)]} 0 1
[junit4:junit4] 2> 684961 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10002 (-1437796750598340609)]} 0 1
[junit4:junit4] 2> 684962 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[2 (-1437796750600437760)]} 0 0
[junit4:junit4] 2> 684963 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10002 (-1437796750601486336)]} 0 0
[junit4:junit4] 2> 684965 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1437796750602534912)]} 0 1
[junit4:junit4] 2> 684965 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10005 (1437796750603583488)]} 0 0
[junit4:junit4] 2> 684967 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1437796750604632064)]} 0 1
[junit4:junit4] 2> 684967 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10005 (1437796750605680640)]} 0 0
[junit4:junit4] 2> 684972 T2401 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 39004
[junit4:junit4] 2> 684972 T2401 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=14565505
[junit4:junit4] 2> 685067 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10006 (1437796750710538240)]} 0 1
[junit4:junit4] 2> 685067 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1437796750710538241)]} 0 1
[junit4:junit4] 2> 685069 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10006 (1437796750712635392)]} 0 0
[junit4:junit4] 2> 685070 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1437796750712635393)]} 0 1
[junit4:junit4] 2> 685091 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10007 (1437796750734655488)]} 0 1
[junit4:junit4] 2> 685091 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1437796750734655489)]} 0 1
[junit4:junit4] 2> 685093 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10007 (1437796750737801216)]} 0 0
[junit4:junit4] 2> 685093 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1437796750737801217)]} 0 0
[junit4:junit4] 2> 685125 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10007 (-1437796750771355648)]} 0 0
[junit4:junit4] 2> 685125 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[7 (-1437796750771355649)]} 0 0
[junit4:junit4] 2> 685127 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10007 (-1437796750773452800)]} 0 0
[junit4:junit4] 2> 685127 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[7 (-1437796750773452801)]} 0 0
[junit4:junit4] 2> 685129 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10008 (1437796750774501376)]} 0 1
[junit4:junit4] 2> 685129 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1437796750775549952)]} 0 0
[junit4:junit4] 2> 685131 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10008 (1437796750776598528)]} 0 1
[junit4:junit4] 2> 685131 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1437796750777647104)]} 0 0
[junit4:junit4] 2> 685146 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[8 (-1437796750793375745)]} 0 0
[junit4:junit4] 2> 685146 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10008 (-1437796750793375744)]} 0 0
[junit4:junit4] 2> 685147 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[8 (-1437796750794424320)]} 0 0
[junit4:junit4] 2> 685148 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10008 (-1437796750795472896)]} 0 0
[junit4:junit4] 2> 685149 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437796750796521472)]} 0 0
[junit4:junit4] 2> 685150 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10009 (1437796750796521473)]} 0 1
[junit4:junit4] 2> 685151 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437796750798618624)]} 0 0
[junit4:junit4] 2> 685152 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10009 (1437796750798618625)]} 0 1
[junit4:junit4] 2> 685181 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 685182 T2424 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39004__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:39004_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39004"}
[junit4:junit4] 2> 685184 T2430 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> 685184 T2459 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> 685184 T2443 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> 685184 T2423 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> 685204 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[9 (-1437796750854193152)]} 0 0
[junit4:junit4] 2> 685205 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10009 (-1437796750855241728)]} 0 0
[junit4:junit4] 2> C2143_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:39004_, base_url=http://127.0.0.1:39004}
[junit4:junit4] 2> 685212 T2453 C2143 P39004 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 685213 T2453 C2143 P39004 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 685213 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10009 (-1437796750857338880)]} 0 2
[junit4:junit4] 2> 685213 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[9 (-1437796750856290304)]} 0 0
[junit4:junit4] 2> 685214 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10009 (-1437796750857338880)]} 0 7
[junit4:junit4] 2> 685214 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[9 (-1437796750856290304)]} 0 8
[junit4:junit4] 2> 685216 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10010 (1437796750866776064)]} 0 0
[junit4:junit4] 2> 685216 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1437796750866776065)]} 0 0
[junit4:junit4] 2> 685220 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10010 (1437796750868873216)]} 0 0
[junit4:junit4] 2> 685221 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437796750868873217)]} 0 1
[junit4:junit4] 2> 685221 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10010 (1437796750868873216)]} 0 3
[junit4:junit4] 2> 685221 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1437796750868873217)]} 0 3
[junit4:junit4] 2> 685314 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10011 (1437796750969536512)]} 0 0
[junit4:junit4] 2> 685314 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437796750969536513)]} 0 0
[junit4:junit4] 2> 685319 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10011 (1437796750971633664)]} 0 1
[junit4:junit4] 2> 685319 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437796750972682240)]} 0 1
[junit4:junit4] 2> 685319 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10011 (1437796750971633664)]} 0 3
[junit4:junit4] 2> 685319 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437796750972682240)]} 0 2
[junit4:junit4] 2> 685359 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1437796751015673856)]} 0 1
[junit4:junit4] 2> 685359 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10012 (1437796751015673857)]} 0 1
[junit4:junit4] 2> 685363 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437796751018819584)]} 0 0
[junit4:junit4] 2> 685363 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10012 (1437796751018819585)]} 0 0
[junit4:junit4] 2> 685363 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1437796751018819584)]} 0 2
[junit4:junit4] 2> 685363 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10012 (1437796751018819585)]} 0 2
[junit4:junit4] 2> 685463 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[11 (-1437796751125774336)]} 0 0
[junit4:junit4] 2> 685464 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10011 (-1437796751125774337)]} 0 1
[junit4:junit4] 2> 685467 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10011 (-1437796751128920065)]} 0 0
[junit4:junit4] 2> 685467 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[11 (-1437796751128920064)]} 0 0
[junit4:junit4] 2> 685468 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10011 (-1437796751128920065)]} 0 2
[junit4:junit4] 2> 685468 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[11 (-1437796751128920064)]} 0 2
[junit4:junit4] 2> 685470 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10013 (1437796751133114368)]} 0 0
[junit4:junit4] 2> 685470 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437796751133114369)]} 0 0
[junit4:junit4] 2> 685474 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10013 (1437796751135211520)]} 0 0
[junit4:junit4] 2> 685474 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437796751135211521)]} 0 0
[junit4:junit4] 2> 685475 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10013 (1437796751135211520)]} 0 3
[junit4:junit4] 2> 685475 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437796751135211521)]} 0 3
[junit4:junit4] 2> 685568 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10014 (1437796751235874817)]} 0 0
[junit4:junit4] 2> 685569 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1437796751235874816)]} 0 1
[junit4:junit4] 2> 685573 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10014 (1437796751239020544)]} 0 1
[junit4:junit4] 2> 685573 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437796751239020545)]} 0 1
[junit4:junit4] 2> 685573 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10014 (1437796751239020544)]} 0 2
[junit4:junit4] 2> 685573 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1437796751239020545)]} 0 2
[junit4:junit4] 2> 685592 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10012 (-1437796751261040640)]} 0 0
[junit4:junit4] 2> 685592 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[12 (-1437796751261040641)]} 0 0
[junit4:junit4] 2> 685596 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10012 (-1437796751263137792)]} 0 0
[junit4:junit4] 2> 685596 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[12 (-1437796751264186368)]} 0 0
[junit4:junit4] 2> 685596 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10012 (-1437796751263137792)]} 0 2
[junit4:junit4] 2> 685597 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[12 (-1437796751264186368)]} 0 2
[junit4:junit4] 2> 685599 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10015 (1437796751267332096)]} 0 1
[junit4:junit4] 2> 685599 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1437796751268380672)]} 0 1
[junit4:junit4] 2> 685603 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10015 (1437796751270477824)]} 0 0
[junit4:junit4] 2> 685603 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437796751270477825)]} 0 0
[junit4:junit4] 2> 685603 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10015 (1437796751270477824)]} 0 2
[junit4:junit4] 2> 685604 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1437796751270477825)]} 0 3
[junit4:junit4] 2> 685627 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10015 (-1437796751297740800)]} 0 1
[junit4:junit4] 2> 685627 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[15 (-1437796751297740801)]} 0 1
[junit4:junit4] 2> 685630 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10015 (-1437796751299837952)]} 0 0
[junit4:junit4] 2> 685630 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[15 (-1437796751299837953)]} 0 0
[junit4:junit4] 2> 685631 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10015 (-1437796751299837952)]} 0 3
[junit4:junit4] 2> 685631 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[15 (-1437796751299837953)]} 0 2
[junit4:junit4] 2> 685633 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10016 (1437796751304032256)]} 0 0
[junit4:junit4] 2> 685633 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1437796751304032257)]} 0 0
[junit4:junit4] 2> 685637 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10016 (1437796751306129408)]} 0 1
[junit4:junit4] 2> 685637 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437796751306129409)]} 0 0
[junit4:junit4] 2> 685637 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10016 (1437796751306129408)]} 0 2
[junit4:junit4] 2> 685638 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1437796751306129409)]} 0 3
[junit4:junit4] 2> 685664 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10017 (1437796751335489536)]} 0 1
[junit4:junit4] 2> 685664 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1437796751336538112)]} 0 1
[junit4:junit4] 2> 685668 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10017 (1437796751338635264)]} 0 1
[junit4:junit4] 2> 685668 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437796751338635265)]} 0 0
[junit4:junit4] 2> 685668 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10017 (1437796751338635264)]} 0 2
[junit4:junit4] 2> 685668 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1437796751338635265)]} 0 2
[junit4:junit4] 2> 685766 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10018 (1437796751442444288)]} 0 1
[junit4:junit4] 2> 685766 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437796751442444289)]} 0 1
[junit4:junit4] 2> 685770 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1437796751445590016)]} 0 1
[junit4:junit4] 2> 685770 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437796751445590017)]} 0 1
[junit4:junit4] 2> 685770 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10018 (1437796751445590016)]} 0 2
[junit4:junit4] 2> 685770 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437796751445590017)]} 0 2
[junit4:junit4] 2> 685771 T2436 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:39004__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 685772 T2436 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:39004__collection1&state=recovering&nodeName=127.0.0.1:39004_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 685849 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437796751529476097)]} 0 1
[junit4:junit4] 2> 685849 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10019 (1437796751529476096)]} 0 1
[junit4:junit4] 2> 685853 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437796751532621824)]} 0 0
[junit4:junit4] 2> 685853 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1437796751532621825)]} 0 0
[junit4:junit4] 2> 685854 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437796751532621824)]} 0 3
[junit4:junit4] 2> 685854 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10019 (1437796751532621825)]} 0 3
[junit4:junit4] 2> 685896 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[18 (-1437796751579807744)]} 0 0
[junit4:junit4] 2> 685896 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10018 (-1437796751579807745)]} 0 0
[junit4:junit4] 2> 685900 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[18 (-1437796751581904896)]} 0 0
[junit4:junit4] 2> 685900 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10018 (-1437796751581904897)]} 0 0
[junit4:junit4] 2> 685900 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[18 (-1437796751581904896)]} 0 2
[junit4:junit4] 2> 685900 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10018 (-1437796751581904897)]} 0 2
[junit4:junit4] 2> 685902 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1437796751586099200)]} 0 0
[junit4:junit4] 2> 685903 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10020 (1437796751586099201)]} 0 1
[junit4:junit4] 2> 685906 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437796751588196352)]} 0 0
[junit4:junit4] 2> 685907 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1437796751588196353)]} 0 1
[junit4:junit4] 2> 685907 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1437796751588196352)]} 0 3
[junit4:junit4] 2> 685907 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10020 (1437796751588196353)]} 0 3
[junit4:junit4] 2> 685972 T2401 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 685973 T2401 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 685974 T2401 oasc.RecoveryStrategy.close WARN Stopping recovery for zkNodeName=127.0.0.1:39004__collection1core=collection1
[junit4:junit4] 2> 685986 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437796751674179584)]} 0 0
[junit4:junit4] 2> 685987 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10021 (1437796751674179585)]} 0 1
[junit4:junit4] 2> 685991 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437796751676276736)]} 0 1
[junit4:junit4] 2> 685991 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1437796751677325312)]} 0 1
[junit4:junit4] 2> 685991 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437796751676276736)]} 0 3
[junit4:junit4] 2> 685991 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10021 (1437796751677325312)]} 0 3
[junit4:junit4] 2> 686031 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[19 (-1437796751721365504)]} 0 0
[junit4:junit4] 2> 686031 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10019 (-1437796751721365505)]} 0 0
[junit4:junit4] 2> 686035 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[19 (-1437796751723462656)]} 0 0
[junit4:junit4] 2> 686035 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10019 (-1437796751723462657)]} 0 0
[junit4:junit4] 2> 686035 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[19 (-1437796751723462656)]} 0 2
[junit4:junit4] 2> 686036 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10019 (-1437796751723462657)]} 0 3
[junit4:junit4] 2> 686038 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1437796751727656960)]} 0 1
[junit4:junit4] 2> 686038 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10022 (1437796751727656961)]} 0 1
[junit4:junit4] 2> 686041 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437796751729754112)]} 0 0
[junit4:junit4] 2> 686041 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1437796751729754113)]} 0 0
[junit4:junit4] 2> 686042 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1437796751729754112)]} 0 3
[junit4:junit4] 2> 686042 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10022 (1437796751729754113)]} 0 3
[junit4:junit4] 2> 686071 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437796751763308544)]} 0 0
[junit4:junit4] 2> 686071 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10023 (1437796751763308545)]} 0 0
[junit4:junit4] 2> 686075 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437796751765405696)]} 0 0
[junit4:junit4] 2> 686075 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1437796751765405697)]} 0 0
[junit4:junit4] 2> 686075 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437796751765405696)]} 0 2
[junit4:junit4] 2> 686076 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10023 (1437796751765405697)]} 0 3
[junit4:junit4] 2> 686132 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[20 (-1437796751826223105)]} 0 1
[junit4:junit4] 2> 686132 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10020 (-1437796751826223104)]} 0 1
[junit4:junit4] 2> 686135 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[20 (-1437796751829368832)]} 0 0
[junit4:junit4] 2> 686135 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10020 (-1437796751829368833)]} 0 0
[junit4:junit4] 2> 686135 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[20 (-1437796751829368832)]} 0 1
[junit4:junit4] 2> 686136 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10020 (-1437796751829368833)]} 0 2
[junit4:junit4] 2> 686138 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437796751832514560)]} 0 1
[junit4:junit4] 2> 686138 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10024 (1437796751833563136)]} 0 1
[junit4:junit4] 2> 686141 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437796751834611712)]} 0 0
[junit4:junit4] 2> 686142 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1437796751835660288)]} 0 1
[junit4:junit4] 2> 686142 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437796751834611712)]} 0 3
[junit4:junit4] 2> 686142 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10024 (1437796751835660288)]} 0 2
[junit4:junit4] 2> 686213 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10025 (1437796751911157761)]} 0 1
[junit4:junit4] 2> 686213 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437796751911157760)]} 0 1
[junit4:junit4] 2> 686217 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1437796751914303488)]} 0 1
[junit4:junit4] 2> 686217 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437796751914303489)]} 0 0
[junit4:junit4] 2> 686217 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10025 (1437796751914303488)]} 0 2
[junit4:junit4] 2> 686218 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437796751914303489)]} 0 3
[junit4:junit4] 2> 686318 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10026 (1437796752022306816)]} 0 1
[junit4:junit4] 2> 686318 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437796752022306817)]} 0 0
[junit4:junit4] 2> 686322 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1437796752024403968)]} 0 0
[junit4:junit4] 2> 686322 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437796752024403969)]} 0 0
[junit4:junit4] 2> 686322 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10026 (1437796752024403968)]} 0 2
[junit4:junit4] 2> 686323 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437796752024403969)]} 0 3
[junit4:junit4] 2> 686368 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10022 (-1437796752073687040)]} 0 1
[junit4:junit4] 2> 686368 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[22 (-1437796752074735616)]} 0 0
[junit4:junit4] 2> 686371 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10022 (-1437796752076832768)]} 0 0
[junit4:junit4] 2> 686371 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[22 (-1437796752076832769)]} 0 0
[junit4:junit4] 2> 686372 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10022 (-1437796752076832768)]} 0 2
[junit4:junit4] 2> 686372 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[22 (-1437796752076832769)]} 0 2
[junit4:junit4] 2> 686374 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10027 (1437796752081027072)]} 0 0
[junit4:junit4] 2> 686374 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437796752081027073)]} 0 0
[junit4:junit4] 2> 686378 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1437796752083124224)]} 0 1
[junit4:junit4] 2> 686378 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437796752083124225)]} 0 0
[junit4:junit4] 2> 686378 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10027 (1437796752083124224)]} 0 2
[junit4:junit4] 2> 686378 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437796752083124225)]} 0 2
[junit4:junit4] 2> 686417 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10028 (1437796752125067264)]} 0 1
[junit4:junit4] 2> 686417 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437796752125067265)]} 0 1
[junit4:junit4] 2> 686421 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1437796752128212992)]} 0 1
[junit4:junit4] 2> 686421 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10028 (1437796752128212992)]} 0 2
[junit4:junit4] 2> 686421 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437796752128212993)]} 0 0
[junit4:junit4] 2> 686422 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437796752128212993)]} 0 3
[junit4:junit4] 2> 686457 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10023 (-1437796752168058880)]} 0 0
[junit4:junit4] 2> 686458 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[23 (-1437796752169107456)]} 0 0
[junit4:junit4] 2> 686461 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10023 (-1437796752170156032)]} 0 0
[junit4:junit4] 2> 686461 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10023 (-1437796752170156032)]} 0 2
[junit4:junit4] 2> 686461 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[23 (-1437796752171204608)]} 0 0
[junit4:junit4] 2> 686462 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[23 (-1437796752171204608)]} 0 2
[junit4:junit4] 2> 686463 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10029 (1437796752174350336)]} 0 0
[junit4:junit4] 2> 686464 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1437796752175398912)]} 0 0
[junit4:junit4] 2> 686467 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1437796752176447488)]} 0 0
[junit4:junit4] 2> 686467 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437796752176447489)]} 0 0
[junit4:junit4] 2> 686468 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10029 (1437796752176447488)]} 0 3
[junit4:junit4] 2> 686468 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1437796752176447489)]} 0 3
[junit4:junit4] 2> 686495 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10030 (1437796752207904768)]} 0 0
[junit4:junit4] 2> 686496 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1437796752207904769)]} 0 1
[junit4:junit4] 2> 686499 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1437796752210001920)]} 0 0
[junit4:junit4] 2> 686500 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437796752211050496)]} 0 1
[junit4:junit4] 2> 686500 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10030 (1437796752210001920)]} 0 3
[junit4:junit4] 2> 686500 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1437796752211050496)]} 0 2
[junit4:junit4] 2> 686565 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10025 (-1437796752281305088)]} 0 0
[junit4:junit4] 2> 686565 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[25 (-1437796752281305089)]} 0 0
[junit4:junit4] 2> 686568 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10025 (-1437796752283402240)]} 0 0
[junit4:junit4] 2> 686569 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[25 (-1437796752283402241)]} 0 1
[junit4:junit4] 2> 686569 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10025 (-1437796752283402240)]} 0 2
[junit4:junit4] 2> 686569 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[25 (-1437796752283402241)]} 0 2
[junit4:junit4] 2> 686571 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10031 (1437796752287596544)]} 0 0
[junit4:junit4] 2> 686571 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437796752287596545)]} 0 0
[junit4:junit4] 2> 686575 T2455 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1437796752289693696)]} 0 1
[junit4:junit4] 2> 686575 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10031 (1437796752289693696)]} 0 2
[junit4:junit4] 2> 686575 T2452 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437796752289693697)]} 0 0
[junit4:junit4] 2> 686576 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437796752289693697)]} 0 3
[junit4:junit4] 2> 686619 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10032 (1437796752337928192)]} 0 0
[junit4:junit4] 2> 686620 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437796752338976768)]} 0 0
[junit4:junit4] 2> 686623 T2454 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10032 (1437796752340025344)]} 0 0
[junit4:junit4] 2> 686624 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10032 (1437796752340025344)]} 0 3
[junit4:junit4] 2> 686624 T2453 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48496/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437796752341073920)]} 0 1
[junit4:junit4] 2> 686624 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437796752341073920)]} 0 2
[junit4:junit4] 2> 686687 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 686687 T2424 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39004__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:39004_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39004"}
[junit4:junit4] 2> 686690 T2443 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> 686690 T2423 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> 686690 T2430 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> 686690 T2459 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> 686714 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10026 (-1437796752436494336)]} 0 1
[junit4:junit4] 2> 686714 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[26 (-1437796752437542912)]} 0 0
[junit4:junit4] 2> 686715 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10026 (-1437796752438591488)]} 0 0
[junit4:junit4] 2> 686716 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[26 (-1437796752439640064)]} 0 0
[junit4:junit4] 2> 686717 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10033 (1437796752440688640)]} 0 0
[junit4:junit4] 2> 686718 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437796752441737216)]} 0 0
[junit4:junit4] 2> 686719 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10033 (1437796752442785792)]} 0 0
[junit4:junit4] 2> 686720 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437796752443834368)]} 0 1
[junit4:junit4] 2> 686721 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10027 (-1437796752444882944)]} 0 0
[junit4:junit4] 2> 686721 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[27 (-1437796752444882945)]} 0 0
[junit4:junit4] 2> 686722 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10027 (-1437796752445931520)]} 0 0
[junit4:junit4] 2> 686723 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[27 (-1437796752446980096)]} 0 0
[junit4:junit4] 2> 686724 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10034 (1437796752448028672)]} 0 0
[junit4:junit4] 2> 686725 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437796752449077248)]} 0 0
[junit4:junit4] 2> 686726 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10034 (1437796752450125824)]} 0 0
[junit4:junit4] 2> 686727 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437796752451174400)]} 0 0
[junit4:junit4] 2> 686760 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10035 (1437796752485777408)]} 0 0
[junit4:junit4] 2> 686761 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1437796752486825984)]} 0 0
[junit4:junit4] 2> 686762 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10035 (1437796752487874560)]} 0 0
[junit4:junit4] 2> 686764 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1437796752488923136)]} 0 1
[junit4:junit4] 2> 686826 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10036 (1437796752553934848)]} 0 1
[junit4:junit4] 2> 686827 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437796752556032000)]} 0 0
[junit4:junit4] 2> 686828 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10036 (1437796752556032000)]} 0 1
[junit4:junit4] 2> 686829 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437796752558129152)]} 0 0
[junit4:junit4] 2> 686907 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10037 (1437796752639918080)]} 0 0
[junit4:junit4] 2> 686908 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437796752640966656)]} 0 0
[junit4:junit4] 2> 686909 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10037 (1437796752642015232)]} 0 0
[junit4:junit4] 2> 686910 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437796752643063808)]} 0 0
[junit4:junit4] 2> 686996 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10038 (1437796752732192768)]} 0 1
[junit4:junit4] 2> 686996 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437796752733241344)]} 0 0
[junit4:junit4] 2> 686998 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10038 (1437796752735338496)]} 0 0
[junit4:junit4] 2> 686998 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437796752735338497)]} 0 0
[junit4:junit4] 2> 687000 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10031 (-1437796752737435648)]} 0 0
[junit4:junit4] 2> 687000 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[31 (-1437796752737435649)]} 0 0
[junit4:junit4] 2> 687002 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10031 (-1437796752739532800)]} 0 0
[junit4:junit4] 2> 687002 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[31 (-1437796752739532801)]} 0 0
[junit4:junit4] 2> 687004 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10039 (1437796752741629952)]} 0 0
[junit4:junit4] 2> 687004 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437796752741629953)]} 0 0
[junit4:junit4] 2> 687006 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10039 (1437796752743727104)]} 0 0
[junit4:junit4] 2> 687006 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437796752743727105)]} 0 0
[junit4:junit4] 2> 687053 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10040 (1437796752791961601)]} 0 1
[junit4:junit4] 2> 687053 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437796752791961600)]} 0 1
[junit4:junit4] 2> 687055 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10040 (1437796752795107328)]} 0 1
[junit4:junit4] 2> 687055 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437796752795107329)]} 0 0
[junit4:junit4] 2> 687126 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1437796752868507648)]} 0 1
[junit4:junit4] 2> 687126 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10041 (1437796752868507649)]} 0 1
[junit4:junit4] 2> 687128 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1437796752871653376)]} 0 1
[junit4:junit4] 2> 687128 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10041 (1437796752871653377)]} 0 0
[junit4:junit4] 2> 687194 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[32 (-1437796752940859393)]} 0 0
[junit4:junit4] 2> 687194 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10032 (-1437796752940859392)]} 0 0
[junit4:junit4] 2> 687197 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[32 (-1437796752944005120)]} 0 1
[junit4:junit4] 2> 687197 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10032 (-1437796752944005121)]} 0 0
[junit4:junit4] 2> 687199 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1437796752946102272)]} 0 1
[junit4:junit4] 2> 687199 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10042 (1437796752946102273)]} 0 0
[junit4:junit4] 2> 687201 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1437796752948199424)]} 0 0
[junit4:junit4] 2> 687201 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10042 (1437796752948199425)]} 0 0
[junit4:junit4] 2> 687289 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10033 (-1437796753039425536)]} 0 1
[junit4:junit4] 2> 687289 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[33 (-1437796753039425537)]} 0 1
[junit4:junit4] 2> 687291 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10033 (-1437796753042571264)]} 0 1
[junit4:junit4] 2> 687291 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[33 (-1437796753042571265)]} 0 0
[junit4:junit4] 2> 687293 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10043 (1437796753044668416)]} 0 0
[junit4:junit4] 2> 687293 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437796753044668417)]} 0 0
[junit4:junit4] 2> 687295 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10043 (1437796753046765568)]} 0 0
[junit4:junit4] 2> 687296 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437796753046765569)]} 0 1
[junit4:junit4] 2> 687363 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10044 (1437796753117020160)]} 0 1
[junit4:junit4] 2> 687363 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437796753117020161)]} 0 1
[junit4:junit4] 2> 687365 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10044 (1437796753120165888)]} 0 0
[junit4:junit4] 2> 687365 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437796753120165889)]} 0 0
[junit4:junit4] 2> 687416 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10034 (-1437796753173643264)]} 0 0
[junit4:junit4] 2> 687416 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[34 (-1437796753173643265)]} 0 0
[junit4:junit4] 2> 687418 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10034 (-1437796753175740416)]} 0 0
[junit4:junit4] 2> 687418 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[34 (-1437796753175740417)]} 0 0
[junit4:junit4] 2> 687420 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10045 (1437796753177837568)]} 0 0
[junit4:junit4] 2> 687421 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437796753177837569)]} 0 1
[junit4:junit4] 2> 687422 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10045 (1437796753179934720)]} 0 0
[junit4:junit4] 2> 687423 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437796753180983296)]} 0 0
[junit4:junit4] 2> 687457 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10046 (1437796753215586304)]} 0 1
[junit4:junit4] 2> 687457 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1437796753216634880)]} 0 0
[junit4:junit4] 2> 687459 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10046 (1437796753218732032)]} 0 0
[junit4:junit4] 2> 687459 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1437796753218732033)]} 0 0
[junit4:junit4] 2> 687527 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10036 (-1437796753290035200)]} 0 0
[junit4:junit4] 2> 687527 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[36 (-1437796753290035201)]} 0 0
[junit4:junit4] 2> 687529 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10036 (-1437796753292132352)]} 0 0
[junit4:junit4] 2> 687530 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[36 (-1437796753292132353)]} 0 1
[junit4:junit4] 2> 687531 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10047 (1437796753294229504)]} 0 0
[junit4:junit4] 2> 687532 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1437796753294229505)]} 0 1
[junit4:junit4] 2> 687534 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10047 (1437796753296326656)]} 0 1
[junit4:junit4] 2> 687534 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1437796753297375232)]} 0 1
[junit4:junit4] 2> 687576 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10048 (1437796753341415424)]} 0 0
[junit4:junit4] 2> 687576 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437796753341415425)]} 0 0
[junit4:junit4] 2> 687579 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10048 (1437796753343512576)]} 0 1
[junit4:junit4] 2> 687579 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437796753343512577)]} 0 1
[junit4:junit4] 2> 687667 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437796753436835840)]} 0 0
[junit4:junit4] 2> 687667 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10049 (1437796753436835841)]} 0 0
[junit4:junit4] 2> 687669 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437796753438932992)]} 0 0
[junit4:junit4] 2> 687670 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10049 (1437796753438932993)]} 0 1
[junit4:junit4] 2> 687755 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437796753528061952)]} 0 1
[junit4:junit4] 2> 687755 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10050 (1437796753528061953)]} 0 1
[junit4:junit4] 2> 687757 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437796753531207680)]} 0 0
[junit4:junit4] 2> 687757 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10050 (1437796753531207681)]} 0 0
[junit4:junit4] 2> 687762 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[38 (-1437796753536450560)]} 0 0
[junit4:junit4] 2> 687762 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10038 (-1437796753536450561)]} 0 0
[junit4:junit4] 2> 687764 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[38 (-1437796753538547712)]} 0 0
[junit4:junit4] 2> 687764 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10038 (-1437796753538547713)]} 0 0
[junit4:junit4] 2> 687766 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437796753540644864)]} 0 0
[junit4:junit4] 2> 687766 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10051 (1437796753540644865)]} 0 0
[junit4:junit4] 2> 687768 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437796753542742016)]} 0 0
[junit4:junit4] 2> 687768 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10051 (1437796753542742017)]} 0 0
[junit4:junit4] 2> C2143_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:39004_, base_url=http://127.0.0.1:39004}
[junit4:junit4] 2> 687772 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:48496/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 687772 T2462 C2143 P39004 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39004 START replicas=[http://127.0.0.1:48496/collection1/] nUpdates=100
[junit4:junit4] 2> 687773 T2462 C2143 P39004 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 687773 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 687773 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 687774 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 687774 T2462 C2143 P39004 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/tlog/tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 687774 T2437 C2145 P48496 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 687774 T2462 C2143 P39004 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:48496/collection1/. core=collection1
[junit4:junit4] 2> 687774 T2462 C2143 P39004 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 687777 T2439 C2145 P48496 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 687788 T2439 C2145 P48496 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b1f41a),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1221db0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b1f41a),segFN=segments_2,generation=2}
[junit4:junit4] 2> 687788 T2439 C2145 P48496 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 687789 T2439 C2145 P48496 oass.SolrIndexSearcher.<init> Opening Searcher@93ed89 realtime
[junit4:junit4] 2> 687789 T2439 C2145 P48496 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 687790 T2439 C2145 P48496 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 13
[junit4:junit4] 2> 687790 T2462 C2143 P39004 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 687790 T2462 C2143 P39004 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 687792 T2436 C2145 P48496 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 687792 T2436 C2145 P48496 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 687793 T2462 C2143 P39004 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 687793 T2462 C2143 P39004 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 687793 T2462 C2143 P39004 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 687795 T2437 C2145 P48496 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> 687795 T2462 C2143 P39004 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 5
[junit4:junit4] 2> 687796 T2462 C2143 P39004 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index.20130614020356094
[junit4:junit4] 2> 687796 T2462 C2143 P39004 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1c7c2dc lockFactory=org.apache.lucene.store.NativeFSLockFactory@16bdbab) fullCopy=false
[junit4:junit4] 2> 687799 T2439 C2145 P48496 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=_0.cfs&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 687802 T2438 C2145 P48496 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> 687805 T2436 C2145 P48496 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> 687807 T2437 C2145 P48496 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> 687809 T2439 C2145 P48496 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> 687810 T2462 C2143 P39004 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 687810 T2462 C2143 P39004 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 687811 T2462 C2143 P39004 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 687811 T2462 C2143 P39004 oasu.DefaultSolrCoreState.newIndexWriter Closing old IndexWriter... core=collection1
[junit4:junit4] 2> 687816 T2462 C2143 P39004 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 687816 T2462 C2143 P39004 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 687817 T2462 C2143 P39004 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 687818 T2462 C2143 P39004 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 687818 T2462 C2143 P39004 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 687818 T2462 C2143 P39004 oass.SolrIndexSearcher.<init> Opening Searcher@901c41 main
[junit4:junit4] 2> 687819 T2461 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@901c41 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c46/18)}
[junit4:junit4] 2> 687820 T2462 C2143 P39004 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index.20130614020356094 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index.20130614020356094;done=true>>]
[junit4:junit4] 2> 687820 T2462 C2143 P39004 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index.20130614020356094
[junit4:junit4] 2> 687820 T2462 C2143 P39004 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index.20130614020356094
[junit4:junit4] 2> 687820 T2462 C2143 P39004 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 687820 T2470 C2143 P39004 oasu.UpdateLog$LogReplayer.doReplay WARN Starting log replay tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/tlog/tlog.0000000000000000000 refcount=2} active=true starting pos=6628
[junit4:junit4] 2> 687821 T2470 C2143 P39004 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 687821 T2470 C2143 P39004 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1510709 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15f47a1),segFN=segments_3,generation=3}
[junit4:junit4] 2> 687822 T2470 C2143 P39004 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 687822 T2470 C2143 P39004 oass.SolrIndexSearcher.<init> Opening Searcher@6e76bf main
[junit4:junit4] 2> 687822 T2470 C2143 P39004 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 687823 T2461 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e76bf main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c46/18)}
[junit4:junit4] 2> 687823 T2470 C2143 P39004 oasup.LogUpdateProcessor.finish [collection1] {} 0 3
[junit4:junit4] 2> 687823 T2470 C2143 P39004 oasu.UpdateLog$LogReplayer.run WARN Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=6628}
[junit4:junit4] 2> 687824 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 687824 T2462 C2143 P39004 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 687824 T2462 C2143 P39004 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 687825 T2462 C2143 P39004 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 687825 T2401 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@dc76dd
[junit4:junit4] 2> 687829 T2401 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=20,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 687829 T2401 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 687830 T2401 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 687830 T2401 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 687830 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437796753607753728)]} 0 0
[junit4:junit4] 2> 687831 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10052 (1437796753607753729)]} 0 1
[junit4:junit4] 2> 687831 T2401 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 687831 T2401 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 687832 T2401 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index;done=false>>]
[junit4:junit4] 2> 687832 T2401 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index
[junit4:junit4] 2> 687832 T2401 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2;done=false>>]
[junit4:junit4] 2> 687833 T2401 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2
[junit4:junit4] 2> 687833 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437796753609850880)]} 0 1
[junit4:junit4] 2> 687833 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10052 (1437796753610899456)]} 0 0
[junit4:junit4] 2> 687834 T2459 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> 687834 T2430 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> 687834 T2423 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 687834 T2459 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 687835 T2423 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> 687835 T2459 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 687835 T2443 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 687836 T2443 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> 687836 T2430 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 687856 T2401 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 687915 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[43 (-1437796753696882688)]} 0 0
[junit4:junit4] 2> 687916 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10043 (-1437796753696882689)]} 0 1
[junit4:junit4] 2> 687918 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[43 (-1437796753700028416)]} 0 1
[junit4:junit4] 2> 687918 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10043 (-1437796753700028417)]} 0 0
[junit4:junit4] 2> 687920 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1437796753701076992)]} 0 1
[junit4:junit4] 2> 687920 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10053 (1437796753701076993)]} 0 1
[junit4:junit4] 2> 687922 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1437796753703174144)]} 0 1
[junit4:junit4] 2> 687922 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10053 (1437796753704222720)]} 0 0
[junit4:junit4] 2> 687988 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[44 (-1437796753773428737)]} 0 0
[junit4:junit4] 2> 687988 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10044 (-1437796753773428736)]} 0 0
[junit4:junit4] 2> 687990 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[44 (-1437796753775525888)]} 0 0
[junit4:junit4] 2> 687990 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10044 (-1437796753775525889)]} 0 0
[junit4:junit4] 2> 687992 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437796753777623040)]} 0 0
[junit4:junit4] 2> 687992 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10054 (1437796753777623041)]} 0 0
[junit4:junit4] 2> 687994 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437796753779720192)]} 0 0
[junit4:junit4] 2> 687995 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10054 (1437796753779720193)]} 0 1
[junit4:junit4] 2> 688005 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437796753790205952)]} 0 1
[junit4:junit4] 2> 688005 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10055 (1437796753790205953)]} 0 1
[junit4:junit4] 2> 688007 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437796753792303104)]} 0 1
[junit4:junit4] 2> 688007 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10055 (1437796753793351680)]} 0 0
[junit4:junit4] 2> 688075 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10049 (-1437796753864654848)]} 0 0
[junit4:junit4] 2> 688075 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[49 (-1437796753864654849)]} 0 0
[junit4:junit4] 2> 688077 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10049 (-1437796753866752000)]} 0 0
[junit4:junit4] 2> 688077 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[49 (-1437796753866752001)]} 0 0
[junit4:junit4] 2> 688079 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10056 (1437796753867800576)]} 0 1
[junit4:junit4] 2> 688079 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1437796753868849152)]} 0 0
[junit4:junit4] 2> 688081 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10056 (1437796753870946304)]} 0 0
[junit4:junit4] 2> 688081 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1437796753870946305)]} 0 0
[junit4:junit4] 2> 688115 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10050 (-1437796753906597888)]} 0 0
[junit4:junit4] 2> 688115 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[50 (-1437796753906597889)]} 0 0
[junit4:junit4] 2> 688117 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10050 (-1437796753908695040)]} 0 0
[junit4:junit4] 2> 688117 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[50 (-1437796753908695041)]} 0 0
[junit4:junit4] 2> 688119 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10057 (1437796753909743616)]} 0 1
[junit4:junit4] 2> 688119 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437796753910792192)]} 0 0
[junit4:junit4] 2> 688121 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10057 (1437796753912889344)]} 0 0
[junit4:junit4] 2> 688121 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437796753912889345)]} 0 0
[junit4:junit4] 2> 688162 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[51 (-1437796753955880961)]} 0 0
[junit4:junit4] 2> 688162 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10051 (-1437796753955880960)]} 0 0
[junit4:junit4] 2> 688164 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[51 (-1437796753957978112)]} 0 0
[junit4:junit4] 2> 688164 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10051 (-1437796753957978113)]} 0 0
[junit4:junit4] 2> 688166 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437796753960075264)]} 0 1
[junit4:junit4] 2> 688166 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10058 (1437796753960075265)]} 0 0
[junit4:junit4] 2> 688168 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437796753962172416)]} 0 0
[junit4:junit4] 2> 688168 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10058 (1437796753962172417)]} 0 0
[junit4:junit4] 2> 688193 T2424 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 688193 T2424 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:39004__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:39004_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39004"}
[junit4:junit4] 2> 688195 T2430 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> 688196 T2423 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> 688196 T2443 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> 688231 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10053 (-1437796754028232704)]} 0 0
[junit4:junit4] 2> 688231 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[53 (-1437796754028232705)]} 0 0
[junit4:junit4] 2> 688233 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10053 (-1437796754030329856)]} 0 0
[junit4:junit4] 2> 688233 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[53 (-1437796754030329857)]} 0 0
[junit4:junit4] 2> 688235 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10059 (1437796754032427008)]} 0 0
[junit4:junit4] 2> 688235 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437796754032427009)]} 0 0
[junit4:junit4] 2> 688237 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10059 (1437796754034524160)]} 0 0
[junit4:junit4] 2> 688237 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437796754034524161)]} 0 0
[junit4:junit4] 2> 688262 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10060 (1437796754060738560)]} 0 0
[junit4:junit4] 2> 688262 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1437796754060738561)]} 0 0
[junit4:junit4] 2> 688265 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10060 (1437796754062835712)]} 0 1
[junit4:junit4] 2> 688265 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1437796754063884288)]} 0 1
[junit4:junit4] 2> 688336 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[54 (-1437796754138333184)]} 0 0
[junit4:junit4] 2> 688336 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10054 (-1437796754138333185)]} 0 0
[junit4:junit4] 2> 688338 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[54 (-1437796754140430336)]} 0 0
[junit4:junit4] 2> 688339 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10054 (-1437796754141478912)]} 0 0
[junit4:junit4] 2> 688341 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437796754142527488)]} 0 1
[junit4:junit4] 2> 688341 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10061 (1437796754143576064)]} 0 0
[junit4:junit4] 2> 688344 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437796754145673216)]} 0 1
[junit4:junit4] 2> 688344 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10061 (1437796754146721792)]} 0 0
[junit4:junit4] 2> 688400 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[56 (-1437796754205442048)]} 0 0
[junit4:junit4] 2> 688401 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10056 (-1437796754206490624)]} 0 0
[junit4:junit4] 2> 688402 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[56 (-1437796754207539200)]} 0 0
[junit4:junit4] 2> 688403 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10056 (-1437796754208587776)]} 0 0
[junit4:junit4] 2> 688404 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437796754209636352)]} 0 0
[junit4:junit4] 2> 688405 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10062 (1437796754209636353)]} 0 1
[junit4:junit4] 2> 688406 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437796754211733504)]} 0 0
[junit4:junit4] 2> 688407 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10062 (1437796754211733505)]} 0 1
[junit4:junit4] 2> 688467 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[59 (-1437796754275696640)]} 0 0
[junit4:junit4] 2> 688468 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10059 (-1437796754276745216)]} 0 0
[junit4:junit4] 2> 688469 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[59 (-1437796754277793792)]} 0 0
[junit4:junit4] 2> 688469 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10059 (-1437796754277793793)]} 0 0
[junit4:junit4] 2> 688471 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1437796754279890944)]} 0 0
[junit4:junit4] 2> 688471 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10063 (1437796754279890945)]} 0 0
[junit4:junit4] 2> 688473 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1437796754281988096)]} 0 0
[junit4:junit4] 2> 688474 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10063 (1437796754283036672)]} 0 0
[junit4:junit4] 2> 688479 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[60 (-1437796754288279552)]} 0 1
[junit4:junit4] 2> 688479 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10060 (-1437796754288279553)]} 0 0
[junit4:junit4] 2> 688481 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[60 (-1437796754290376704)]} 0 0
[junit4:junit4] 2> 688481 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10060 (-1437796754290376705)]} 0 0
[junit4:junit4] 2> 688483 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1437796754292473856)]} 0 0
[junit4:junit4] 2> 688484 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10064 (1437796754293522432)]} 0 1
[junit4:junit4] 2> 688485 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1437796754294571008)]} 0 0
[junit4:junit4] 2> 688487 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10064 (1437796754295619584)]} 0 1
[junit4:junit4] 2> 688499 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[62 (-1437796754309251072)]} 0 0
[junit4:junit4] 2> 688501 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10062 (-1437796754311348224)]} 0 1
[junit4:junit4] 2> 688501 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[62 (-1437796754311348224)]} 0 0
[junit4:junit4] 2> 688502 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10062 (-1437796754312396800)]} 0 0
[junit4:junit4] 2> 688503 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1437796754313445376)]} 0 0
[junit4:junit4] 2> 688504 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10065 (1437796754314493952)]} 0 0
[junit4:junit4] 2> 688505 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1437796754315542528)]} 0 0
[junit4:junit4] 2> 688506 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10065 (1437796754316591104)]} 0 0
[junit4:junit4] 2> 688525 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437796754336514048)]} 0 0
[junit4:junit4] 2> 688527 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10066 (1437796754337562624)]} 0 1
[junit4:junit4] 2> 688527 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437796754338611200)]} 0 0
[junit4:junit4] 2> 688529 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10066 (1437796754340708352)]} 0 0
[junit4:junit4] 2> 688615 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437796754429837312)]} 0 1
[junit4:junit4] 2> 688616 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10067 (1437796754431934464)]} 0 0
[junit4:junit4] 2> 688617 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437796754432983040)]} 0 0
[junit4:junit4] 2> 688619 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10067 (1437796754434031616)]} 0 0
[junit4:junit4] 2> 688670 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437796754488557568)]} 0 0
[junit4:junit4] 2> 688672 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10068 (1437796754489606144)]} 0 1
[junit4:junit4] 2> 688672 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437796754490654720)]} 0 0
[junit4:junit4] 2> 688674 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10068 (1437796754491703296)]} 0 1
[junit4:junit4] 2> 688682 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1437796754501140480)]} 0 0
[junit4:junit4] 2> 688684 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10069 (1437796754502189056)]} 0 1
[junit4:junit4] 2> 688684 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1437796754503237632)]} 0 0
[junit4:junit4] 2> 688686 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10069 (1437796754504286208)]} 0 1
[junit4:junit4] 2> 688694 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1437796754513723392)]} 0 0
[junit4:junit4] 2> 688696 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10070 (1437796754514771968)]} 0 1
[junit4:junit4] 2> 688696 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1437796754515820544)]} 0 0
[junit4:junit4] 2> 688698 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10070 (1437796754516869120)]} 0 1
[junit4:junit4] 2> 688781 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1437796754603900928)]} 0 1
[junit4:junit4] 2> 688782 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10071 (1437796754604949504)]} 0 1
[junit4:junit4] 2> 688783 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1437796754607046656)]} 0 0
[junit4:junit4] 2> 688784 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10071 (1437796754607046657)]} 0 1
[junit4:junit4] 2> 688821 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1437796754646892544)]} 0 0
[junit4:junit4] 2> 688822 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10072 (1437796754646892545)]} 0 1
[junit4:junit4] 2> 688823 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1437796754648989696)]} 0 0
[junit4:junit4] 2> 688824 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10072 (1437796754648989697)]} 0 0
[junit4:junit4] 2> 688892 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1437796754720292864)]} 0 1
[junit4:junit4] 2> 688892 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10073 (1437796754720292865)]} 0 1
[junit4:junit4] 2> 688894 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1437796754723438592)]} 0 0
[junit4:junit4] 2> 688894 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10073 (1437796754723438593)]} 0 0
[junit4:junit4] 2> 688937 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[73 (-1437796754768527360)]} 0 0
[junit4:junit4] 2> 688937 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10073 (-1437796754768527361)]} 0 0
[junit4:junit4] 2> 688939 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[73 (-1437796754770624512)]} 0 0
[junit4:junit4] 2> 688939 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10073 (-1437796754770624513)]} 0 0
[junit4:junit4] 2> 688941 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[74 (1437796754772721664)]} 0 0
[junit4:junit4] 2> 688941 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10074 (1437796754772721665)]} 0 0
[junit4:junit4] 2> 688943 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[74 (1437796754774818816)]} 0 0
[junit4:junit4] 2> 688943 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10074 (1437796754774818817)]} 0 0
[junit4:junit4] 2> 688950 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[75 (1437796754782158848)]} 0 0
[junit4:junit4] 2> 688951 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10075 (1437796754782158849)]} 0 1
[junit4:junit4] 2> 688953 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[75 (1437796754784256000)]} 0 1
[junit4:junit4] 2> 688953 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10075 (1437796754784256001)]} 0 1
[junit4:junit4] 2> 689036 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10076 (1437796754872336385)]} 0 1
[junit4:junit4] 2> 689036 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[76 (1437796754872336384)]} 0 1
[junit4:junit4] 2> 689038 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10076 (1437796754874433536)]} 0 0
[junit4:junit4] 2> 689038 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[76 (1437796754874433537)]} 0 0
[junit4:junit4] 2> 689113 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10077 (1437796754952028160)]} 0 1
[junit4:junit4] 2> 689113 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[77 (1437796754952028161)]} 0 1
[junit4:junit4] 2> 689115 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10077 (1437796754955173888)]} 0 1
[junit4:junit4] 2> 689115 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[77 (1437796754955173889)]} 0 0
[junit4:junit4] 2> 689207 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10076 (-1437796755051642880)]} 0 0
[junit4:junit4] 2> 689207 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[76 (-1437796755051642881)]} 0 0
[junit4:junit4] 2> 689209 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10076 (-1437796755053740032)]} 0 0
[junit4:junit4] 2> 689209 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[76 (-1437796755053740033)]} 0 0
[junit4:junit4] 2> 689211 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10078 (1437796755055837184)]} 0 0
[junit4:junit4] 2> 689211 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[78 (1437796755055837185)]} 0 0
[junit4:junit4] 2> 689213 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10078 (1437796755057934336)]} 0 0
[junit4:junit4] 2> 689214 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[78 (1437796755057934337)]} 0 1
[junit4:junit4] 2> 689248 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10079 (1437796755094634496)]} 0 0
[junit4:junit4] 2> 689248 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[79 (1437796755094634497)]} 0 0
[junit4:junit4] 2> 689250 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10079 (1437796755096731648)]} 0 0
[junit4:junit4] 2> 689250 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[79 (1437796755096731649)]} 0 0
[junit4:junit4] 2> 689307 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10079 (-1437796755156500480)]} 0 0
[junit4:junit4] 2> 689307 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[79 (-1437796755156500481)]} 0 0
[junit4:junit4] 2> 689310 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10079 (-1437796755159646208)]} 0 1
[junit4:junit4] 2> 689310 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[79 (-1437796755159646209)]} 0 0
[junit4:junit4] 2> 689312 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10080 (1437796755160694784)]} 0 1
[junit4:junit4] 2> 689312 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[80 (1437796755161743360)]} 0 0
[junit4:junit4] 2> 689314 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10080 (1437796755162791936)]} 0 1
[junit4:junit4] 2> 689314 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[80 (1437796755163840512)]} 0 0
[junit4:junit4] 2> 689362 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[81 (1437796755214172160)]} 0 0
[junit4:junit4] 2> 689362 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10081 (1437796755214172161)]} 0 0
[junit4:junit4] 2> 689364 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[81 (1437796755216269312)]} 0 0
[junit4:junit4] 2> 689365 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10081 (1437796755216269313)]} 0 1
[junit4:junit4] 2> 689396 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[82 (1437796755249823744)]} 0 1
[junit4:junit4] 2> 689396 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10082 (1437796755249823745)]} 0 0
[junit4:junit4] 2> 689398 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[82 (1437796755251920896)]} 0 0
[junit4:junit4] 2> 689398 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10082 (1437796755251920897)]} 0 0
[junit4:junit4] 2> 689474 T2418 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[82 (-1437796755331612672)]} 0 0
[junit4:junit4] 2> 689474 T2416 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10082 (-1437796755331612673)]} 0 0
[junit4:junit4] 2> 689476 T2436 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[82 (-1437796755333709824)]} 0 0
[junit4:junit4] 2> 689477 T2439 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10082 (-1437796755334758400)]} 0 0
[junit4:junit4] 2> 689479 T2417 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[83 (1437796755335806976)]} 0 1
[junit4:junit4] 2> 689479 T2419 C2144 P40648 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10083 (1437796755335806977)]} 0 1
[junit4:junit4] 2> 689481 T2438 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[83 (1437796755337904128)]} 0 1
[junit4:junit4] 2> 689481 T2437 C2145 P48496 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10083 (1437796755338952704)]} 0 0
[junit4:junit4] 2> 689501 T2418 C2144 P40648 oasup.Log
[...truncated too long message...]
ader.
[junit4:junit4] 2> 783988 T2483 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 783989 T2483 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39004/collection1/
[junit4:junit4] 2> 783989 T2483 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 783989 T2483 oasc.SyncStrategy.syncToMe http://127.0.0.1:39004/collection1/ has no replicas
[junit4:junit4] 2> 783990 T2483 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39004/collection1/
[junit4:junit4] 2> 783990 T2483 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 783990 T2495 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:48496__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:48496_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48496"}
[junit4:junit4] 2> 783996 T2483 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> 784000 T2401 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 784053 T2401 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 39004
[junit4:junit4] 2> 784053 T2401 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=12408826
[junit4:junit4] 2> 785054 T2401 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 785055 T2401 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 785056 T2401 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@10e0eea
[junit4:junit4] 2> 785060 T2401 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=68,cumulative_deletesById=18,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 785060 T2401 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 785061 T2401 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 785061 T2401 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 785062 T2401 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 785063 T2401 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 785063 T2401 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2;done=false>>]
[junit4:junit4] 2> 785063 T2401 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2
[junit4:junit4] 2> 785063 T2401 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index;done=false>>]
[junit4:junit4] 2> 785064 T2401 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371189824144/jetty2/index
[junit4:junit4] 2> 785064 T2495 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89862296315297802-127.0.0.1:39004_-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 785087 T2401 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 785141 T2401 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 785143 T2401 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:54410 54410
[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=366A568BB4C93CB7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_GT -Dtests.timezone=Brazil/West -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 109s J1 | RecoveryZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: expected:<250> but was:<54>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([366A568BB4C93CB7:B78CD893C3965C8B]:0)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 785158 T2401 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 109319 T2400 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 4 leaked thread(s).
[junit4:junit4] 2> 785278 T2443 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 785278 T2443 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> 785278 T2443 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 786366 T2483 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 786366 T2483 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> 786366 T2483 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=DefaultSimilarity, locale=es_GT, timezone=Brazil/West
[junit4:junit4] 2> NOTE: Linux 3.2.0-45-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=1,free=20670672,total=292945920
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestLazyCores, SimplePostToolTest, ZkSolrClientTest, HighlighterConfigTest, TestPartialUpdateDeduplication, DistanceFunctionTest, TestClassNameShortening, TestMergePolicyConfig, OutputWriterTest, TestFieldResource, TestAddFieldRealTimeGet, TestBinaryResponseWriter, TestUniqueKeyFieldResource, SpellCheckComponentTest, TestAtomicUpdateErrorCases, HighlighterTest, TestCSVLoader, NoCacheHeaderTest, SortByFunctionTest, TestQueryTypes, TestPostingsSolrHighlighter, BasicZkTest, TestDFRSimilarityFactory, DirectSolrSpellCheckerTest, TestIndexSearcher, SolrRequestParserTest, TestQuerySenderNoQuery, SolrCoreCheckLockOnStartupTest, TestSchemaNameResource, CurrencyFieldOpenExchangeTest, LeaderElectionIntegrationTest, TestHashPartitioner, TestArbitraryIndexDir, FieldAnalysisRequestHandlerTest, SpellCheckCollatorTest, SampleTest, TestReload, SolrCmdDistributorTest, TestDynamicFieldCollectionResource, TestShardHandlerFactory, TestSolrQueryParserResource, TestFieldTypeCollectionResource, TestUtils, TestFieldTypeResource, SuggesterTSTTest, TestLMJelinekMercerSimilarityFactory, TestBM25SimilarityFactory, TestManagedSchemaFieldResource, DisMaxRequestHandlerTest, TestFiltering, CoreContainerCoreInitFailuresTest, TestFastOutputStream, DateMathParserTest, TestSolr4Spatial, NotRequiredUniqueKeyTest, SignatureUpdateProcessorFactoryTest, DebugComponentTest, IndexBasedSpellCheckerTest, XsltUpdateRequestHandlerTest, StandardRequestHandlerTest, SuggesterWFSTTest, TestMultiCoreConfBootstrap, TestRTGBase, TestDistributedGrouping, TestJmxMonitoredMap, TestJmxIntegration, TestNumberUtils, OpenExchangeRatesOrgProviderTest, BasicDistributedZkTest, ChaosMonkeySafeLeaderTest, CollectionsAPIDistributedZkTest, OpenCloseCoreStressTest, RecoveryZkTest]
[junit4:junit4] Completed on J1 in 110.59s, 1 test, 1 failure <<< FAILURES!
[...truncated 428 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:385: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:365: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 296 suites, 1243 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 37 minutes 22 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -server -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure