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/16 01:36:36 UTC
[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_21) - Build #
2933 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2933/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.RecoveryZkTest.testDistribSearch
Error Message:
expected:<200> but was:<35>
Stack Trace:
java.lang.AssertionError: expected:<200> but was:<35>
at __randomizedtesting.SeedInfo.seed([A0D53E6014E53113:2133B07863BA512F]: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 9257 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 646506 T943 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /he/hz
[junit4:junit4] 2> 646511 T943 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-RecoveryZkTest-1371336882263
[junit4:junit4] 2> 646513 T943 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 646514 T944 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 646613 T943 oasc.ZkTestServer.run start zk server on port:51193
[junit4:junit4] 2> 646614 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 646623 T950 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53da85f3 name:ZooKeeperConnection Watcher:127.0.0.1:51193 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 646624 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 646624 T943 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 646632 T945 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f4a0c38610000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 646635 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 646640 T952 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48eb4622 name:ZooKeeperConnection Watcher:127.0.0.1:51193/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 646640 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 646640 T943 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 646649 T943 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 646656 T943 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 646662 T943 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 646668 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 646670 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 646680 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 646680 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 646688 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 646689 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 646700 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 646701 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 646714 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 646715 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 646722 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 646724 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 646730 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 646731 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 646738 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 646740 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 646747 T943 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 646748 T943 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 646758 T945 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f4a0c38610001, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 647153 T943 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 647163 T943 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51200
[junit4:junit4] 2> 647164 T943 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 647164 T943 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 647165 T943 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509
[junit4:junit4] 2> 647165 T943 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509\solr.xml
[junit4:junit4] 2> 647165 T943 oasc.CoreContainer.<init> New CoreContainer 2022482655
[junit4:junit4] 2> 647166 T943 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509\'
[junit4:junit4] 2> 647166 T943 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509\'
[junit4:junit4] 2> 647280 T943 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 647280 T943 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 647281 T943 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 647281 T943 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 647281 T943 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 647282 T943 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 647283 T943 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 647283 T943 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 647283 T943 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 647284 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 647293 T943 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 647294 T943 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51193/solr
[junit4:junit4] 2> 647295 T943 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 647296 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 647313 T963 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@368b8a89 name:ZooKeeperConnection Watcher:127.0.0.1:51193 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 647314 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 647319 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 647326 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 647331 T965 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e623fb6 name:ZooKeeperConnection Watcher:127.0.0.1:51193/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 647331 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 647335 T943 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 647345 T943 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 647354 T943 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 647359 T943 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51200_he%2Fhz
[junit4:junit4] 2> 647362 T943 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51200_he%2Fhz
[junit4:junit4] 2> 647369 T943 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 647385 T943 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 647391 T943 oasc.Overseer.start Overseer (id=89871933916643331-127.0.0.1:51200_he%2Fhz-n_0000000000) starting
[junit4:junit4] 2> 647401 T943 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 647412 T967 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 647415 T943 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 647421 T943 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 647427 T943 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 647434 T966 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 647440 T968 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 647441 T968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 648919 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 648921 T966 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:51200_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51200/he/hz"}
[junit4:junit4] 2> 648921 T966 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 648921 T966 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 648936 T965 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> 649412 T968 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509\collection1
[junit4:junit4] 2> 649412 T968 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 649414 T968 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 649414 T968 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 649418 T968 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509\collection1\'
[junit4:junit4] 2> 649419 T968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 649420 T968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509/collection1/lib/README' to classloader
[junit4:junit4] 2> 649473 T968 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 649538 T968 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 649541 T968 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 649547 T968 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 650178 T968 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 650187 T968 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 650192 T968 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 650219 T968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 650225 T968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 650231 T968 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 650234 T968 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 650234 T968 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 650234 T968 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 650235 T968 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 650235 T968 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 650236 T968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 650236 T968 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1371336882509\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/control/data\
[junit4:junit4] 2> 650236 T968 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4dd84aaf
[junit4:junit4] 2> 650237 T968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 650238 T968 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/control/data\
[junit4:junit4] 2> 650238 T968 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/control/data\index/
[junit4:junit4] 2> 650238 T968 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 650238 T968 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/control/data\index
[junit4:junit4] 2> 650243 T968 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@188afa25 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70dd58ce),segFN=segments_1,generation=1}
[junit4:junit4] 2> 650243 T968 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 650247 T968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 650247 T968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 650249 T968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 650249 T968 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 650250 T968 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 650250 T968 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 650250 T968 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 650251 T968 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 650251 T968 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 650261 T968 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 650269 T968 oass.SolrIndexSearcher.<init> Opening Searcher@19189903 main
[junit4:junit4] 2> 650269 T968 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\control\data\tlog
[junit4:junit4] 2> 650271 T968 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 650272 T968 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 650275 T969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19189903 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 650277 T968 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 650277 T968 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51200/he/hz collection:control_collection shard:shard1
[junit4:junit4] 2> 650278 T968 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 650305 T968 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 650312 T968 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 650312 T968 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 650313 T968 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51200/he/hz/collection1/
[junit4:junit4] 2> 650313 T968 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 650313 T968 oasc.SyncStrategy.syncToMe http://127.0.0.1:51200/he/hz/collection1/ has no replicas
[junit4:junit4] 2> 650314 T968 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51200/he/hz/collection1/
[junit4:junit4] 2> 650314 T968 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 650422 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 650440 T965 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> 650483 T968 oasc.ZkController.register We are http://127.0.0.1:51200/he/hz/collection1/ and leader is http://127.0.0.1:51200/he/hz/collection1/
[junit4:junit4] 2> 650483 T968 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51200/he/hz
[junit4:junit4] 2> 650483 T968 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 650484 T968 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 650484 T968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 650488 T968 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 650491 T943 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 650491 T943 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 650491 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 650505 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 650509 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 650513 T972 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cbec24b name:ZooKeeperConnection Watcher:127.0.0.1:51193/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 650513 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 650516 T943 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 650522 T943 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 650996 T943 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 651001 T943 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51212
[junit4:junit4] 2> 651002 T943 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 651002 T943 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 651003 T943 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273
[junit4:junit4] 2> 651003 T943 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273\solr.xml
[junit4:junit4] 2> 651003 T943 oasc.CoreContainer.<init> New CoreContainer 393178735
[junit4:junit4] 2> 651003 T943 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273\'
[junit4:junit4] 2> 651005 T943 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273\'
[junit4:junit4] 2> 651117 T943 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 651118 T943 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 651118 T943 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 651119 T943 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 651119 T943 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 651119 T943 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 651120 T943 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 651120 T943 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 651120 T943 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 651121 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 651129 T943 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 651130 T943 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51193/solr
[junit4:junit4] 2> 651131 T943 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 651133 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 651149 T983 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4df52953 name:ZooKeeperConnection Watcher:127.0.0.1:51193 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 651149 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 651155 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 651156 T945 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f4a0c38610005, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 651164 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 651169 T985 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@44a19af5 name:ZooKeeperConnection Watcher:127.0.0.1:51193/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 651169 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 651179 T943 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 651930 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 651931 T966 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51200_he%2Fhz_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:51200_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51200/he/hz"}
[junit4:junit4] 2> 651946 T985 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> 651947 T972 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> 651948 T965 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> 652171 T943 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51212_he%2Fhz
[junit4:junit4] 2> 652175 T943 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51212_he%2Fhz
[junit4:junit4] 2> 652181 T965 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> 652182 T972 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> 652183 T985 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 652184 T985 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> 652187 T965 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 652187 T972 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 652197 T986 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 652197 T986 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 653434 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653436 T966 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:51212_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51212/he/hz"}
[junit4:junit4] 2> 653436 T966 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 653436 T966 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 653449 T972 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> 653450 T965 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> 653450 T985 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> 654170 T986 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273\collection1
[junit4:junit4] 2> 654170 T986 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 654171 T986 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 654171 T986 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 654174 T986 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273\collection1\'
[junit4:junit4] 2> 654176 T986 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 654177 T986 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273/collection1/lib/README' to classloader
[junit4:junit4] 2> 654239 T986 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 654303 T986 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 654307 T986 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 654312 T986 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 654934 T986 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 654947 T986 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 654951 T986 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 654978 T986 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 654982 T986 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 654988 T986 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 654990 T986 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 654991 T986 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 654991 T986 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 654993 T986 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 654993 T986 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 654993 T986 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 654994 T986 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1371336886273\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty1\
[junit4:junit4] 2> 654994 T986 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4dd84aaf
[junit4:junit4] 2> 654994 T986 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 654995 T986 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty1\
[junit4:junit4] 2> 654995 T986 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty1\index/
[junit4:junit4] 2> 654995 T986 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 654996 T986 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty1\index
[junit4:junit4] 2> 655000 T986 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab2b774 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8eec016),segFN=segments_1,generation=1}
[junit4:junit4] 2> 655000 T986 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 655004 T986 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 655004 T986 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 655004 T986 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 655005 T986 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 655005 T986 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 655005 T986 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 655006 T986 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 655006 T986 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 655007 T986 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 655017 T986 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 655025 T986 oass.SolrIndexSearcher.<init> Opening Searcher@5e26e840 main
[junit4:junit4] 2> 655026 T986 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\jetty1\tlog
[junit4:junit4] 2> 655027 T986 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 655027 T986 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 655032 T987 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e26e840 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 655034 T986 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 655034 T986 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51212/he/hz collection:collection1 shard:shard1
[junit4:junit4] 2> 655036 T986 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 655056 T986 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 655070 T986 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 655071 T986 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 655071 T986 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51212/he/hz/collection1/
[junit4:junit4] 2> 655071 T986 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 655071 T986 oasc.SyncStrategy.syncToMe http://127.0.0.1:51212/he/hz/collection1/ has no replicas
[junit4:junit4] 2> 655071 T986 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51212/he/hz/collection1/
[junit4:junit4] 2> 655071 T986 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 656340 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 656358 T972 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> 656359 T965 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> 656358 T985 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> 656402 T986 oasc.ZkController.register We are http://127.0.0.1:51212/he/hz/collection1/ and leader is http://127.0.0.1:51212/he/hz/collection1/
[junit4:junit4] 2> 656402 T986 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51212/he/hz
[junit4:junit4] 2> 656402 T986 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 656402 T986 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 656403 T986 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 656406 T986 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 656408 T943 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 656408 T943 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 656408 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 656776 T943 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 656780 T943 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51221
[junit4:junit4] 2> 656782 T943 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 656783 T943 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 656783 T943 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168
[junit4:junit4] 2> 656784 T943 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168\solr.xml
[junit4:junit4] 2> 656784 T943 oasc.CoreContainer.<init> New CoreContainer 1915185921
[junit4:junit4] 2> 656784 T943 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168\'
[junit4:junit4] 2> 656785 T943 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168\'
[junit4:junit4] 2> 656883 T943 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 656883 T943 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 656884 T943 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 656884 T943 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 656884 T943 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 656885 T943 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 656885 T943 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 656886 T943 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 656887 T943 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 656887 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 656894 T943 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 656895 T943 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51193/solr
[junit4:junit4] 2> 656895 T943 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 656898 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 656912 T999 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19f476e5 name:ZooKeeperConnection Watcher:127.0.0.1:51193 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 656912 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 656917 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 656925 T943 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 656929 T1001 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@490893bb name:ZooKeeperConnection Watcher:127.0.0.1:51193/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 656930 T943 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 656938 T943 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 657699 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657700 T966 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51212_he%2Fhz_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:51212_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51212/he/hz"}
[junit4:junit4] 2> 657711 T972 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> 657711 T985 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> 657712 T965 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> 657711 T1001 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> 657830 T943 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51221_he%2Fhz
[junit4:junit4] 2> 657832 T943 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51221_he%2Fhz
[junit4:junit4] 2> 657836 T972 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> 657836 T1001 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> 657837 T965 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> 657838 T985 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 657839 T985 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> 657841 T972 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 657842 T1001 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 657842 T965 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 657850 T1002 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 657851 T1002 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 659050 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 659051 T966 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:51221_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51221/he/hz"}
[junit4:junit4] 2> 659051 T966 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 659051 T966 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 659062 T1001 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> 659062 T985 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> 659062 T965 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> 659063 T972 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> 659624 T1002 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168\collection1
[junit4:junit4] 2> 659624 T1002 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 659625 T1002 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 659626 T1002 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 659629 T1002 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168\collection1\'
[junit4:junit4] 2> 659629 T1002 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 659630 T1002 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168/collection1/lib/README' to classloader
[junit4:junit4] 2> 659677 T1002 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 659732 T1002 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 659735 T1002 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 659740 T1002 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 660301 T1002 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 660310 T1002 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 660314 T1002 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 660335 T1002 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 660340 T1002 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 660347 T1002 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 660348 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 660348 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 660349 T1002 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 660351 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 660351 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 660351 T1002 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 660352 T1002 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1371336892168\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\
[junit4:junit4] 2> 660352 T1002 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4dd84aaf
[junit4:junit4] 2> 660352 T1002 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 660353 T1002 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\
[junit4:junit4] 2> 660353 T1002 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index/
[junit4:junit4] 2> 660353 T1002 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 660353 T1002 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index
[junit4:junit4] 2> 660358 T1002 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 660358 T1002 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 660362 T1002 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 660362 T1002 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 660363 T1002 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 660364 T1002 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 660365 T1002 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 660365 T1002 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 660365 T1002 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 660366 T1002 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 660366 T1002 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 660376 T1002 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 660383 T1002 oass.SolrIndexSearcher.<init> Opening Searcher@5a7e291a main
[junit4:junit4] 2> 660384 T1002 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\jetty2\tlog
[junit4:junit4] 2> 660385 T1002 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 660385 T1002 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 660391 T1003 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5a7e291a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 660391 T1002 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 660392 T1002 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51221/he/hz collection:collection1 shard:shard1
[junit4:junit4] 2> 660403 T1002 oasc.ZkController.register We are http://127.0.0.1:51221/he/hz/collection1/ and leader is http://127.0.0.1:51212/he/hz/collection1/
[junit4:junit4] 2> 660403 T1002 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51221/he/hz
[junit4:junit4] 2> 660404 T1002 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 660404 T1002 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C3407 name=collection1 org.apache.solr.core.SolrCore@6757b12 url=http://127.0.0.1:51221/he/hz/collection1 node=127.0.0.1:51221_he%2Fhz C3407_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51221_he%2Fhz, base_url=http://127.0.0.1:51221/he/hz}
[junit4:junit4] 2> 660404 T1004 C3407 P51221 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 660405 T1004 C3407 P51221 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 660405 T1004 C3407 P51221 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 660405 T1004 C3407 P51221 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 660406 T1002 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 660409 T1004 C3407 P51221 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 660410 T943 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 660410 T943 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 660411 T943 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 660417 T943 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 660419 T976 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:51221_he%2Fhz_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C3408 name=collection1 org.apache.solr.core.SolrCore@504bdd92 url=http://127.0.0.1:51200/he/hz/collection1 node=127.0.0.1:51200_he%2Fhz C3408_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51200_he%2Fhz, base_url=http://127.0.0.1:51200/he/hz, leader=true}
[junit4:junit4] 2> 660436 T961 C3408 P51200 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@188afa25 lockFactory=org.apache.lucene.store.NativeFSLockFactory@70dd58ce),segFN=segments_1,generation=1}
[junit4:junit4] 2> 660437 T961 C3408 P51200 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 660442 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10001 (1437950957253033984)]} 0 9
[junit4:junit4] 2> 660442 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[1 (1437950957254082560)]} 0 8
[junit4:junit4] 2> ASYNC NEW_CORE C3409 name=collection1 org.apache.solr.core.SolrCore@3fd6e06 url=http://127.0.0.1:51212/he/hz/collection1 node=127.0.0.1:51212_he%2Fhz C3409_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51212_he%2Fhz, base_url=http://127.0.0.1:51212/he/hz, leader=true}
[junit4:junit4] 2> 660459 T978 C3409 P51212 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab2b774 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8eec016),segFN=segments_1,generation=1}
[junit4:junit4] 2> 660460 T978 C3409 P51212 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 660463 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10001 (1437950957276102656)]} 0 8
[junit4:junit4] 2> 660465 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[1 (1437950957283442688)]} 0 3
[junit4:junit4] 2> 660539 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10002 (1437950957361037312)]} 0 3
[junit4:junit4] 2> 660539 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[2 (1437950957362085888)]} 0 3
[junit4:junit4] 2> 660545 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10002 (1437950957370474496)]} 0 1
[junit4:junit4] 2> 660546 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[2 (1437950957370474497)]} 0 1
[junit4:junit4] 2> 660573 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10003 (1437950957398786048)]} 0 2
[junit4:junit4] 2> 660573 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[3 (1437950957398786049)]} 0 1
[junit4:junit4] 2> 660577 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10003 (1437950957404028928)]} 0 1
[junit4:junit4] 2> 660578 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[3 (1437950957404028929)]} 0 1
[junit4:junit4] 2> 660667 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10004 (1437950957498400768)]} 0 1
[junit4:junit4] 2> 660669 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[4 (1437950957499449344)]} 0 1
[junit4:junit4] 2> 660671 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10004 (1437950957501546496)]} 0 1
[junit4:junit4] 2> 660673 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[4 (1437950957504692224)]} 0 1
[junit4:junit4] 2> 660733 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10002 (-1437950957567606784)]} 0 1
[junit4:junit4] 2> 660736 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10002 (-1437950957570752512)]} 0 0
[junit4:junit4] 2> 660737 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[2 (-1437950957571801088)]} 0 0
[junit4:junit4] 2> 660740 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10005 (1437950957573898240)]} 0 1
[junit4:junit4] 2> 660744 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[2 (-1437950957578092544)]} 0 1
[junit4:junit4] 2> 660744 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10005 (1437950957578092545)]} 0 1
[junit4:junit4] 2> 660748 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[5 (1437950957582286848)]} 0 1
[junit4:junit4] 2> 660751 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[5 (1437950957585432576)]} 0 1
[junit4:junit4] 2> 660764 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10004 (-1437950957600112640)]} 0 1
[junit4:junit4] 2> 660767 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10004 (-1437950957603258368)]} 0 0
[junit4:junit4] 2> 660769 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[4 (-1437950957605355520)]} 0 0
[junit4:junit4] 2> 660771 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10006 (1437950957605355521)]} 0 2
[junit4:junit4] 2> 660773 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[4 (-1437950957609549824)]} 0 0
[junit4:junit4] 2> 660775 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10006 (1437950957610598400)]} 0 1
[junit4:junit4] 2> 660776 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[6 (1437950957612695552)]} 0 0
[junit4:junit4] 2> 660779 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[6 (1437950957614792704)]} 0 1
[junit4:junit4] 2> 660816 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10006 (-1437950957654638592)]} 0 0
[junit4:junit4] 2> 660820 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10006 (-1437950957658832896)]} 0 0
[junit4:junit4] 2> 660820 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[6 (-1437950957658832896)]} 0 0
[junit4:junit4] 2> 660823 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10007 (1437950957660930048)]} 0 1
[junit4:junit4] 2> 660823 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[6 (-1437950957661978624)]} 0 0
[junit4:junit4] 2> 660827 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[7 (1437950957665124352)]} 0 1
[junit4:junit4] 2> 660827 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10007 (1437950957665124352)]} 0 1
[junit4:junit4] 2> 660830 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[7 (1437950957669318656)]} 0 1
[junit4:junit4] 2> 660893 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10008 (1437950957734330368)]} 0 1
[junit4:junit4] 2> 660897 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[8 (1437950957738524672)]} 0 1
[junit4:junit4] 2> 660897 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10008 (1437950957738524672)]} 0 1
[junit4:junit4] 2> 660900 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[8 (1437950957741670400)]} 0 1
[junit4:junit4] 2> 660968 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10007 (-1437950957812973568)]} 0 2
[junit4:junit4] 2> 660968 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[7 (-1437950957814022144)]} 0 0
[junit4:junit4] 2> 660970 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10007 (-1437950957816119296)]} 0 0
[junit4:junit4] 2> 660973 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[7 (-1437950957819265024)]} 0 1
[junit4:junit4] 2> 660974 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10009 (1437950957820313600)]} 0 0
[junit4:junit4] 2> 660976 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[9 (1437950957822410752)]} 0 1
[junit4:junit4] 2> 660979 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10009 (1437950957823459328)]} 0 2
[junit4:junit4] 2> 660981 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[9 (1437950957826605056)]} 0 1
[junit4:junit4] 2> 661013 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10008 (-1437950957861208064)]} 0 0
[junit4:junit4] 2> 661015 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[8 (-1437950957863305216)]} 0 0
[junit4:junit4] 2> 661016 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10008 (-1437950957864353792)]} 0 0
[junit4:junit4] 2> 661018 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[8 (-1437950957866450944)]} 0 0
[junit4:junit4] 2> 661019 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10010 (1437950957867499520)]} 0 0
[junit4:junit4] 2> 661022 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10 (1437950957869596672)]} 0 1
[junit4:junit4] 2> 661024 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10010 (1437950957871693824)]} 0 1
[junit4:junit4] 2> 661026 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10 (1437950957873790976)]} 0 1
[junit4:junit4] 2> 661094 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10011 (1437950957945094144)]} 0 2
[junit4:junit4] 2> 661094 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[11 (1437950957946142720)]} 0 0
[junit4:junit4] 2> 661097 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10011 (1437950957948239872)]} 0 1
[junit4:junit4] 2> 661098 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[11 (1437950957948239873)]} 0 2
[junit4:junit4] 2> 661148 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10009 (-1437950958002765824)]} 0 0
[junit4:junit4] 2> 661148 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[9 (-1437950958002765825)]} 0 0
[junit4:junit4] 2> 661151 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10009 (-1437950958005911552)]} 0 0
[junit4:junit4] 2> 661154 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[9 (-1437950958009057280)]} 0 1
[junit4:junit4] 2> 661155 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10012 (1437950958010105856)]} 0 1
[junit4:junit4] 2> 661157 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[12 (1437950958011154432)]} 0 1
[junit4:junit4] 2> 661159 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10012 (1437950958013251584)]} 0 1
[junit4:junit4] 2> 661160 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[12 (1437950958015348736)]} 0 0
[junit4:junit4] 2> 661200 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10010 (-1437950958057291776)]} 0 1
[junit4:junit4] 2> 661202 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10 (-1437950958059388928)]} 0 0
[junit4:junit4] 2> 661204 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10010 (-1437950958061486080)]} 0 1
[junit4:junit4] 2> 661205 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10 (-1437950958062534656)]} 0 0
[junit4:junit4] 2> 661207 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10013 (1437950958063583232)]} 0 1
[junit4:junit4] 2> 661210 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[13 (1437950958067777536)]} 0 1
[junit4:junit4] 2> 661212 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10013 (1437950958067777536)]} 0 2
[junit4:junit4] 2> 661214 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[13 (1437950958070923264)]} 0 1
[junit4:junit4] 2> 661245 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10014 (1437950958104477696)]} 0 1
[junit4:junit4] 2> 661248 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[14 (1437950958106574848)]} 0 1
[junit4:junit4] 2> 661250 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10014 (1437950958108672000)]} 0 1
[junit4:junit4] 2> 661251 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[14 (1437950958110769152)]} 0 1
[junit4:junit4] 2> 661258 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10012 (-1437950958118109184)]} 0 1
[junit4:junit4] 2> 661258 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[12 (-1437950958118109185)]} 0 0
[junit4:junit4] 2> 661262 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10012 (-1437950958122303488)]} 0 1
[junit4:junit4] 2> 661262 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[12 (-1437950958122303489)]} 0 0
[junit4:junit4] 2> 661265 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[15 (1437950958124400640)]} 0 1
[junit4:junit4] 2> 661266 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10015 (1437950958124400641)]} 0 2
[junit4:junit4] 2> 661269 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[15 (1437950958128594944)]} 0 1
[junit4:junit4] 2> 661269 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10015 (1437950958129643520)]} 0 0
[junit4:junit4] 2> 661271 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[13 (-1437950958131740672)]} 0 0
[junit4:junit4] 2> 661273 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10013 (-1437950958132789248)]} 0 1
[junit4:junit4] 2> 661274 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[13 (-1437950958134886400)]} 0 0
[junit4:junit4] 2> 661276 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10013 (-1437950958135934976)]} 0 1
[junit4:junit4] 2> 661278 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[16 (1437950958136983552)]} 0 2
[junit4:junit4] 2> 661279 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10016 (1437950958140129280)]} 0 0
[junit4:junit4] 2> 661282 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[16 (1437950958142226432)]} 0 1
[junit4:junit4] 2> 661285 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10016 (1437950958143275008)]} 0 3
[junit4:junit4] 2> 661353 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10017 (1437950958216675328)]} 0 1
[junit4:junit4] 2> 661354 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[17 (1437950958217723904)]} 0 1
[junit4:junit4] 2> 661355 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10017 (1437950958219821056)]} 0 0
[junit4:junit4] 2> 661358 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[17 (1437950958222966784)]} 0 0
[junit4:junit4] 2> 661378 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10015 (-1437950958243938304)]} 0 2
[junit4:junit4] 2> 661378 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[15 (-1437950958243938305)]} 0 0
[junit4:junit4] 2> 661381 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10015 (-1437950958247084032)]} 0 1
[junit4:junit4] 2> 661381 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[15 (-1437950958247084033)]} 0 0
[junit4:junit4] 2> 661385 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[18 (1437950958250229760)]} 0 1
[junit4:junit4] 2> 661385 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10018 (1437950958250229761)]} 0 1
[junit4:junit4] 2> 661388 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10018 (1437950958253375488)]} 0 1
[junit4:junit4] 2> 661388 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[18 (1437950958253375489)]} 0 1
[junit4:junit4] 2> 661394 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[19 (1437950958259666944)]} 0 1
[junit4:junit4] 2> 661394 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10019 (1437950958259666945)]} 0 1
[junit4:junit4] 2> 661398 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10019 (1437950958263861248)]} 0 1
[junit4:junit4] 2> 661401 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[19 (1437950958265958400)]} 0 2
[junit4:junit4] 2> 661404 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10017 (-1437950958271201280)]} 0 1
[junit4:junit4] 2> 661406 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10017 (-1437950958273298432)]} 0 0
[junit4:junit4] 2> 661406 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[17 (-1437950958273298432)]} 0 0
[junit4:junit4] 2> 661410 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[17 (-1437950958277492736)]} 0 0
[junit4:junit4] 2> 661410 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10020 (1437950958277492736)]} 0 0
[junit4:junit4] 2> 661414 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[20 (1437950958280638464)]} 0 1
[junit4:junit4] 2> 661415 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10020 (1437950958281687040)]} 0 1
[junit4:junit4] 2> 661419 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[20 (1437950958285881344)]} 0 2
[junit4:junit4] 2> 661450 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10019 (-1437950958319435776)]} 0 1
[junit4:junit4] 2> 661454 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10019 (-1437950958323630080)]} 0 1
[junit4:junit4] 2> 661455 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[19 (-1437950958324678656)]} 0 1
[junit4:junit4] 2> 661458 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10021 (1437950958325727232)]} 0 2
[junit4:junit4] 2> 661459 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[19 (-1437950958328872960)]} 0 1
[junit4:junit4] 2> 661462 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10021 (1437950958330970112)]} 0 1
[junit4:junit4] 2> 661464 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[21 (1437950958333067264)]} 0 2
[junit4:junit4] 2> 661468 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[21 (1437950958338310144)]} 0 1
[junit4:junit4] 2> 661497 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10022 (1437950958368718848)]} 0 1
[junit4:junit4] 2> 661500 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10022 (1437950958371864576)]} 0 0
[junit4:junit4] 2> 661504 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[22 (1437950958375010304)]} 0 1
[junit4:junit4] 2> 661507 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[22 (1437950958378156032)]} 0 1
[junit4:junit4] 2> 661595 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10023 (1437950958468333568)]} 0 3
[junit4:junit4] 2> 661599 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[23 (1437950958474625024)]} 0 1
[junit4:junit4] 2> 661600 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10023 (1437950958475673600)]} 0 1
[junit4:junit4] 2> 661602 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[23 (1437950958478819328)]} 0 0
[junit4:junit4] 2> 661636 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10020 (-1437950958514470912)]} 0 0
[junit4:junit4] 2> 661638 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[20 (-1437950958516568064)]} 0 2
[junit4:junit4] 2> 661641 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10020 (-1437950958519713792)]} 0 0
[junit4:junit4] 2> 661644 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[20 (-1437950958522859520)]} 0 0
[junit4:junit4] 2> 661650 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10024 (1437950958524956672)]} 0 4
[junit4:junit4] 2> 661652 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[24 (1437950958530199552)]} 0 1
[junit4:junit4] 2> 661654 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10024 (1437950958533345280)]} 0 1
[junit4:junit4] 2> 661658 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[24 (1437950958536491008)]} 0 1
[junit4:junit4] 2> 661736 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 661740 T966 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51221_he%2Fhz_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:51221_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51221/he/hz"}
[junit4:junit4] 2> 661743 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10021 (-1437950958626668544)]} 0 0
[junit4:junit4] 2> 661750 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[21 (-1437950958634008576)]} 0 0
[junit4:junit4] 2> 661755 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10021 (-1437950958637154304)]} 0 4
[junit4:junit4] 2> 661756 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[21 (-1437950958640300032)]} 0 1
[junit4:junit4] 2> 661762 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10025 (1437950958645542912)]} 0 2
[junit4:junit4] 2> 661764 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[25 (1437950958645542913)]} 0 4
[junit4:junit4] 2> 661769 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10025 (1437950958652882944)]} 0 3
[junit4:junit4] 2> 661769 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[25 (1437950958652882945)]} 0 1
[junit4:junit4] 2> 661773 T972 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> 661773 T985 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> 661774 T1001 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> 661774 T965 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> 661829 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[23 (-1437950958716846081)]} 0 0
[junit4:junit4] 2> 661829 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10023 (-1437950958716846080)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C3410 name=collection1 org.apache.solr.core.SolrCore@6757b12 url=http://127.0.0.1:51221/he/hz/collection1 node=127.0.0.1:51221_he%2Fhz C3410_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51221_he%2Fhz, base_url=http://127.0.0.1:51221/he/hz}
[junit4:junit4] 2> 661880 T993 C3410 P51221 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 661882 T993 C3410 P51221 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 661883 T993 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[23 (-1437950958721040384)]} 0 12
[junit4:junit4] 2> 661884 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[23 (-1437950958721040384)]} 0 51
[junit4:junit4] 2> 661889 T994 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10023 (-1437950958732574720)]} 0 10
[junit4:junit4] 2> 661890 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10023 (-1437950958732574720)]} 0 48
[junit4:junit4] 2> 661891 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[26 (1437950958780809216)]} 0 1
[junit4:junit4] 2> 661894 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10026 (1437950958783954944)]} 0 1
[junit4:junit4] 2> 661896 T995 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437950958782906368)]} 0 0
[junit4:junit4] 2> 661897 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[26 (1437950958782906368)]} 0 5
[junit4:junit4] 2> 661901 T997 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1437950958788149248)]} 0 0
[junit4:junit4] 2> 661902 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10026 (1437950958788149248)]} 0 5
[junit4:junit4] 2> 661932 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[27 (1437950958823800832)]} 0 2
[junit4:junit4] 2> 661936 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10027 (1437950958829043712)]} 0 1
[junit4:junit4] 2> 661942 T996 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437950958829043712)]} 0 1
[junit4:junit4] 2> 661943 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[27 (1437950958829043712)]} 0 7
[junit4:junit4] 2> 661946 T996 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1437950958834286592)]} 0 2
[junit4:junit4] 2> 661946 T980 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10027 (1437950958834286592)]} 0 6
[junit4:junit4] 2> 662005 T958 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[27 (-1437950958900346880)]} 0 1
[junit4:junit4] 2> 662006 T959 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10027 (-1437950958902444032)]} 0 0
[junit4:junit4] 2> 662011 T993 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[27 (-1437950958903492608)]} 0 0
[junit4:junit4] 2> 662012 T981 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[27 (-1437950958903492608)]} 0 5
[junit4:junit4] 2> 662012 T994 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10027 (-1437950958905589760)]} 0 0
[junit4:junit4] 2> 662013 T978 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10027 (-1437950958905589760)]} 0 4
[junit4:junit4] 2> 662014 T954 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[28 (1437950958910832640)]} 0 0
[junit4:junit4] 2> 662017 T957 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10028 (1437950958912929792)]} 0 1
[junit4:junit4] 2> 662020 T995 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437950958915026944)]} 0 0
[junit4:junit4] 2> 662022 T977 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[28 (1437950958915026944)]} 0 4
[junit4:junit4] 2> 662023 T995 C3410 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1437950958916075520)]} 0 1
[junit4:junit4] 2> 662024 T979 C3409 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10028 (1437950958916075520)]} 0 5
[junit4:junit4] 2> 662031 T960 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[29 (1437950958927609856)]} 0 1
[junit4:junit4] 2> 662032 T961 C3408 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10029 (1437950958929707008)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C3411 name=collection1 org.apache.solr.core.SolrCore@6757b12 url=http://127.0.0.1:51221/he/hz/collection1 node=127.0.0.1:51221_he%2Fhz C3411_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51221_he%2Fhz, base_url=http://127.0.0.1:51221/he/hz}
[junit4:junit4] 2> 662043 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437950958930755584)]} 0 6
[junit4:junit4] 2> 662043 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1437950958932852736)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C3412 name=collection1 org.apache.solr.core.SolrCore@3fd6e06 url=http://127.0.0.1:51212/he/hz/collection1 node=127.0.0.1:51212_he%2Fhz C3412_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51212_he%2Fhz, base_url=http://127.0.0.1:51212/he/hz, leader=true}
[junit4:junit4] 2> 662045 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10029 (1437950958932852736)]} 0 10
[junit4:junit4] 2> 662045 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[29 (1437950958930755584)]} 0 12
[junit4:junit4] 2> ASYNC NEW_CORE C3413 name=collection1 org.apache.solr.core.SolrCore@504bdd92 url=http://127.0.0.1:51200/he/hz/collection1 node=127.0.0.1:51200_he%2Fhz C3413_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51200_he%2Fhz, base_url=http://127.0.0.1:51200/he/hz, leader=true}
[junit4:junit4] 2> 662102 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10029 (-1437950959001010176)]} 0 2
[junit4:junit4] 2> 662102 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[29 (-1437950959003107328)]} 0 0
[junit4:junit4] 2> 662107 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10029 (-1437950959005204481)]} 0 0
[junit4:junit4] 2> 662107 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[29 (-1437950959005204480)]} 0 0
[junit4:junit4] 2> 662108 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[29 (-1437950959005204480)]} 0 4
[junit4:junit4] 2> 662109 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10029 (-1437950959005204481)]} 0 5
[junit4:junit4] 2> 662111 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[30 (1437950959011495936)]} 0 1
[junit4:junit4] 2> 662111 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10030 (1437950959012544512)]} 0 0
[junit4:junit4] 2> 662117 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1437950959015690241)]} 0 1
[junit4:junit4] 2> 662117 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437950959015690240)]} 0 1
[junit4:junit4] 2> 662118 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10030 (1437950959015690241)]} 0 4
[junit4:junit4] 2> 662119 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[30 (1437950959015690240)]} 0 5
[junit4:junit4] 2> 662191 T976 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:51221_he%2Fhz_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 662192 T976 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:51221_he%252Fhz_collection1&state=recovering&nodeName=127.0.0.1:51221_he%252Fhz&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1773
[junit4:junit4] 2> 662192 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10031 (1437950959097479168)]} 0 0
[junit4:junit4] 2> 662192 T943 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 51221
[junit4:junit4] 2> 662194 T943 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1915185921
[junit4:junit4] 2> 662192 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[31 (1437950959097479169)]} 0 0
[junit4:junit4] 2> 662201 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1437950959101673472)]} 0 1
[junit4:junit4] 2> 662202 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10031 (1437950959101673472)]} 0 6
[junit4:junit4] 2> 662203 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437950959103770624)]} 0 1
[junit4:junit4] 2> 662203 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[31 (1437950959103770624)]} 0 5
[junit4:junit4] 2> 662291 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10031 (-1437950959201288192)]} 0 1
[junit4:junit4] 2> 662293 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[31 (-1437950959203385344)]} 0 0
[junit4:junit4] 2> 662296 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10031 (-1437950959204433920)]} 0 0
[junit4:junit4] 2> 662297 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10031 (-1437950959204433920)]} 0 3
[junit4:junit4] 2> 662298 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[31 (-1437950959205482496)]} 0 0
[junit4:junit4] 2> 662299 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[31 (-1437950959205482496)]} 0 4
[junit4:junit4] 2> 662301 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10032 (1437950959210725376)]} 0 1
[junit4:junit4] 2> 662302 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[32 (1437950959211773952)]} 0 1
[junit4:junit4] 2> 662307 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10032 (1437950959213871104)]} 0 0
[junit4:junit4] 2> 662308 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10032 (1437950959213871104)]} 0 5
[junit4:junit4] 2> 662309 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437950959215968256)]} 0 1
[junit4:junit4] 2> 662310 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[32 (1437950959215968256)]} 0 5
[junit4:junit4] 2> 662362 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10032 (-1437950959274688512)]} 0 1
[junit4:junit4] 2> 662362 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[32 (-1437950959275737088)]} 0 1
[junit4:junit4] 2> 662370 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10032 (-1437950959279931392)]} 0 0
[junit4:junit4] 2> 662371 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[32 (-1437950959280979968)]} 0 0
[junit4:junit4] 2> 662371 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10032 (-1437950959279931392)]} 0 5
[junit4:junit4] 2> 662373 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[32 (-1437950959280979968)]} 0 6
[junit4:junit4] 2> 662378 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10033 (1437950959291465728)]} 0 2
[junit4:junit4] 2> 662379 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[33 (1437950959292514304)]} 0 1
[junit4:junit4] 2> 662388 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10033 (1437950959296708608)]} 0 2
[junit4:junit4] 2> 662390 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10033 (1437950959296708608)]} 0 8
[junit4:junit4] 2> 662392 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437950959298805760)]} 0 1
[junit4:junit4] 2> 662395 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[33 (1437950959298805760)]} 0 11
[junit4:junit4] 2> 662464 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10033 (-1437950959382691840)]} 0 0
[junit4:junit4] 2> 662468 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[33 (-1437950959386886144)]} 0 0
[junit4:junit4] 2> 662471 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10033 (-1437950959385837568)]} 0 1
[junit4:junit4] 2> 662472 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10033 (-1437950959385837568)]} 0 5
[junit4:junit4] 2> 662474 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10034 (1437950959393177600)]} 0 0
[junit4:junit4] 2> 662477 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[33 (-1437950959392129024)]} 0 1
[junit4:junit4] 2> 662479 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[33 (-1437950959392129024)]} 0 6
[junit4:junit4] 2> 662480 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10034 (1437950959397371904)]} 0 0
[junit4:junit4] 2> 662483 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[34 (1437950959400517632)]} 0 2
[junit4:junit4] 2> 662484 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10034 (1437950959397371904)]} 0 6
[junit4:junit4] 2> 662488 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437950959405760512)]} 0 0
[junit4:junit4] 2> 662490 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[34 (1437950959405760512)]} 0 4
[junit4:junit4] 2> 662509 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10035 (1437950959428829184)]} 0 1
[junit4:junit4] 2> 662514 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[35 (1437950959435120640)]} 0 0
[junit4:junit4] 2> 662517 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10035 (1437950959434072064)]} 0 1
[junit4:junit4] 2> 662518 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10035 (1437950959434072064)]} 0 6
[junit4:junit4] 2> 662524 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437950959440363520)]} 0 1
[junit4:junit4] 2> 662525 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[35 (1437950959440363520)]} 0 6
[junit4:junit4] 2> 662551 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10035 (-1437950959472869376)]} 0 1
[junit4:junit4] 2> 662554 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10035 (-1437950959474966528)]} 0 0
[junit4:junit4] 2> 662555 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10035 (-1437950959474966528)]} 0 3
[junit4:junit4] 2> 662557 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10036 (1437950959480209408)]} 0 0
[junit4:junit4] 2> 662563 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10036 (1437950959484403712)]} 0 0
[junit4:junit4] 2> 662564 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10036 (1437950959484403712)]} 0 4
[junit4:junit4] 2> 662615 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[35 (-1437950959541026816)]} 0 0
[junit4:junit4] 2> 662620 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[35 (-1437950959544172544)]} 0 0
[junit4:junit4] 2> 662621 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[35 (-1437950959544172544)]} 0 3
[junit4:junit4] 2> 662624 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[36 (1437950959549415424)]} 0 1
[junit4:junit4] 2> 662628 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10037 (1437950959554658304)]} 0 1
[junit4:junit4] 2> 662629 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437950959554658304)]} 0 0
[junit4:junit4] 2> 662630 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[36 (1437950959554658304)]} 0 3
[junit4:junit4] 2> 662634 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10037 (1437950959555706880)]} 0 2
[junit4:junit4] 2> 662635 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10037 (1437950959555706880)]} 0 6
[junit4:junit4] 2> 662640 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[37 (1437950959567241216)]} 0 0
[junit4:junit4] 2> 662648 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437950959570386944)]} 0 0
[junit4:junit4] 2> 662649 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[37 (1437950959570386944)]} 0 6
[junit4:junit4] 2> 662666 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10038 (1437950959594504192)]} 0 0
[junit4:junit4] 2> 662676 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10038 (1437950959599747072)]} 0 0
[junit4:junit4] 2> 662678 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10038 (1437950959599747072)]} 0 7
[junit4:junit4] 2> 662681 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[38 (1437950959609184256)]} 0 1
[junit4:junit4] 2> 662691 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437950959614427136)]} 0 1
[junit4:junit4] 2> 662693 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[38 (1437950959614427136)]} 0 8
[junit4:junit4] 2> 662730 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10039 (1437950959660564480)]} 0 2
[junit4:junit4] 2> 662737 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10039 (1437950959663710208)]} 0 1
[junit4:junit4] 2> 662737 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10039 (1437950959663710208)]} 0 5
[junit4:junit4] 2> 662743 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[39 (1437950959674195968)]} 0 1
[junit4:junit4] 2> 662748 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437950959677341696)]} 0 0
[junit4:junit4] 2> 662749 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[39 (1437950959677341696)]} 0 4
[junit4:junit4] 2> 662797 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10040 (1437950959731867648)]} 0 1
[junit4:junit4] 2> 662803 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10040 (1437950959735013376)]} 0 1
[junit4:junit4] 2> 662804 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10040 (1437950959735013376)]} 0 4
[junit4:junit4] 2> 662809 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[40 (1437950959743401984)]} 0 1
[junit4:junit4] 2> 662815 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437950959747596288)]} 0 1
[junit4:junit4] 2> 662816 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[40 (1437950959747596288)]} 0 4
[junit4:junit4] 2> 662838 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10041 (1437950959773810688)]} 0 1
[junit4:junit4] 2> 662848 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10041 (1437950959780102144)]} 0 1
[junit4:junit4] 2> 662852 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10041 (1437950959780102144)]} 0 10
[junit4:junit4] 2> 662852 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[41 (1437950959788490752)]} 0 2
[junit4:junit4] 2> 662860 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437950959795830784)]} 0 0
[junit4:junit4] 2> 662863 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[41 (1437950959795830784)]} 0 5
[junit4:junit4] 2> 662889 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10042 (1437950959828336640)]} 0 0
[junit4:junit4] 2> 662897 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10042 (1437950959832530944)]} 0 0
[junit4:junit4] 2> 662901 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10042 (1437950959832530944)]} 0 9
[junit4:junit4] 2> 662902 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[42 (1437950959839870976)]} 0 2
[junit4:junit4] 2> 662911 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437950959846162432)]} 0 1
[junit4:junit4] 2> 662913 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[42 (1437950959846162432)]} 0 7
[junit4:junit4] 2> 662963 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10043 (1437950959905931264)]} 0 2
[junit4:junit4] 2> 662973 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10043 (1437950959910125568)]} 0 1
[junit4:junit4] 2> 662975 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10043 (1437950959910125568)]} 0 8
[junit4:junit4] 2> 662976 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[43 (1437950959918514176)]} 0 1
[junit4:junit4] 2> 662985 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437950959923757056)]} 0 1
[junit4:junit4] 2> 662987 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[43 (1437950959923757056)]} 0 7
[junit4:junit4] 2> 663039 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10044 (1437950959984574464)]} 0 2
[junit4:junit4] 2> 663047 T992 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10044 (1437950959989817344)]} 0 1
[junit4:junit4] 2> 663050 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10044 (1437950959989817344)]} 0 8
[junit4:junit4] 2> 663050 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[44 (1437950959997157376)]} 0 0
[junit4:junit4] 2> 663058 T994 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437950960002400256)]} 0 0
[junit4:junit4] 2> 663060 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[44 (1437950960002400256)]} 0 5
[junit4:junit4] 2> 663095 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10043 (-1437950960044343296)]} 0 1
[junit4:junit4] 2> 663102 T993 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10043 (-1437950960048537600)]} 0 0
[junit4:junit4] 2> 663104 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10043 (-1437950960048537600)]} 0 6
[junit4:junit4] 2> 663105 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[43 (-1437950960054829056)]} 0 0
[junit4:junit4] 2> 663110 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10045 (1437950960059023360)]} 0 2
[junit4:junit4] 2> 663115 T997 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[43 (-1437950960059023360)]} 0 1
[junit4:junit4] 2> 663117 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[43 (-1437950960059023360)]} 0 8
[junit4:junit4] 2> 663120 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 663123 T966 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51221_he%2Fhz_collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:51221_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51221/he/hz"}
[junit4:junit4] 2> 663123 T995 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10045 (1437950960067411968)]} 0 1
[junit4:junit4] 2> 663126 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10045 (1437950960067411968)]} 0 9
[junit4:junit4] 2> 663127 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[45 (1437950960076849152)]} 0 1
[junit4:junit4] 2> 663137 T996 C3411 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437950960084189184)]} 0 1
[junit4:junit4] 2> 663138 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[45 (1437950960084189184)]} 0 6
[junit4:junit4] 2> 663140 T972 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> 663140 T965 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> 663140 T985 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> 663140 T1001 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> 663209 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10046 (1437950960162832384)]} 0 1
[junit4:junit4] 2> 663214 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10046 (1437950960168075264)]} 0 1
[junit4:junit4] 2> 663221 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[46 (1437950960175415296)]} 0 1
[junit4:junit4] 2> 663226 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[46 (1437950960181706752)]} 0 2
[junit4:junit4] 2> 663273 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10044 (-1437950960230989824)]} 0 0
[junit4:junit4] 2> 663276 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10044 (-1437950960234135552)]} 0 0
[junit4:junit4] 2> 663279 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10047 (1437950960237281280)]} 0 0
[junit4:junit4] 2> 663282 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10047 (1437950960240427008)]} 0 0
[junit4:junit4] 2> 663285 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[44 (-1437950960243572736)]} 0 0
[junit4:junit4] 2> 663288 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[44 (-1437950960246718464)]} 0 0
[junit4:junit4] 2> 663291 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[47 (1437950960248815616)]} 0 1
[junit4:junit4] 2> 663294 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[47 (1437950960251961344)]} 0 1
[junit4:junit4] 2> 663339 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10045 (-1437950960300195840)]} 0 0
[junit4:junit4] 2> 663342 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10045 (-1437950960303341568)]} 0 0
[junit4:junit4] 2> 663345 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10048 (1437950960306487296)]} 0 0
[junit4:junit4] 2> 663347 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10048 (1437950960308584448)]} 0 0
[junit4:junit4] 2> 663349 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[45 (-1437950960310681600)]} 0 0
[junit4:junit4] 2> 663352 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[45 (-1437950960313827328)]} 0 0
[junit4:junit4] 2> 663354 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[48 (1437950960315924480)]} 0 0
[junit4:junit4] 2> 663358 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[48 (1437950960320118784)]} 0 0
[junit4:junit4] 2> 663379 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10047 (-1437950960342138880)]} 0 0
[junit4:junit4] 2> 663383 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10047 (-1437950960346333184)]} 0 0
[junit4:junit4] 2> 663386 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10049 (1437950960348430336)]} 0 1
[junit4:junit4] 2> 663389 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[47 (-1437950960352624640)]} 0 0
[junit4:junit4] 2> 663390 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10049 (1437950960352624640)]} 0 1
[junit4:junit4] 2> 663391 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[47 (-1437950960354721792)]} 0 0
[junit4:junit4] 2> 663395 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[49 (1437950960357867520)]} 0 1
[junit4:junit4] 2> 663396 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[49 (1437950960359964672)]} 0 0
[junit4:junit4] 2> 663438 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10050 (1437950960404004864)]} 0 0
[junit4:junit4] 2> 663441 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10050 (1437950960407150592)]} 0 0
[junit4:junit4] 2> 663445 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[50 (1437950960410296320)]} 0 1
[junit4:junit4] 2> 663448 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[50 (1437950960413442048)]} 0 1
[junit4:junit4] 2> 663459 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10048 (-1437950960426024960)]} 0 0
[junit4:junit4] 2> 663461 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10048 (-1437950960428122112)]} 0 0
[junit4:junit4] 2> 663464 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[48 (-1437950960431267840)]} 0 0
[junit4:junit4] 2> 663465 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10051 (1437950960431267841)]} 0 1
[junit4:junit4] 2> 663467 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[48 (-1437950960434413568)]} 0 0
[junit4:junit4] 2> 663468 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10051 (1437950960434413569)]} 0 1
[junit4:junit4] 2> 663471 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[51 (1437950960437559296)]} 0 1
[junit4:junit4] 2> 663474 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[51 (1437950960440705024)]} 0 1
[junit4:junit4] 2> 663492 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10049 (-1437950960460627968)]} 0 0
[junit4:junit4] 2> 663495 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10049 (-1437950960463773696)]} 0 0
[junit4:junit4] 2> 663498 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[49 (-1437950960466919424)]} 0 0
[junit4:junit4] 2> 663499 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10052 (1437950960466919425)]} 0 1
[junit4:junit4] 2> 663500 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[49 (-1437950960469016576)]} 0 0
[junit4:junit4] 2> 663502 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10052 (1437950960470065152)]} 0 1
[junit4:junit4] 2> 663504 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[52 (1437950960472162304)]} 0 1
[junit4:junit4] 2> 663506 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[52 (1437950960474259456)]} 0 1
[junit4:junit4] 2> 663580 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10053 (1437950960552902656)]} 0 0
[junit4:junit4] 2> 663583 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10053 (1437950960556048384)]} 0 0
[junit4:junit4] 2> 663586 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[53 (1437950960558145536)]} 0 1
[junit4:junit4] 2> 663589 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[53 (1437950960561291264)]} 0 1
[junit4:junit4] 2> 663613 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10053 (-1437950960587505664)]} 0 0
[junit4:junit4] 2> 663618 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[53 (-1437950960592748544)]} 0 0
[junit4:junit4] 2> 663621 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10053 (-1437950960595894272)]} 0 0
[junit4:junit4] 2> 663623 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[53 (-1437950960597991424)]} 0 0
[junit4:junit4] 2> 663625 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10054 (1437950960599040000)]} 0 1
[junit4:junit4] 2> 663627 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[54 (1437950960601137152)]} 0 1
[junit4:junit4] 2> 663627 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10054 (1437950960602185728)]} 0 0
[junit4:junit4] 2> 663629 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[54 (1437950960603234304)]} 0 1
[junit4:junit4] 2> 663681 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10055 (1437950960657760256)]} 0 1
[junit4:junit4] 2> 663683 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[55 (1437950960659857408)]} 0 1
[junit4:junit4] 2> 663685 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10055 (1437950960661954560)]} 0 1
[junit4:junit4] 2> 663685 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[55 (1437950960663003136)]} 0 0
[junit4:junit4] 2> 663753 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10056 (1437950960733257728)]} 0 1
[junit4:junit4] 2> 663754 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[56 (1437950960734306304)]} 0 1
[junit4:junit4] 2> 663755 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10056 (1437950960736403456)]} 0 0
[junit4:junit4] 2> 663756 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[56 (1437950960737452032)]} 0 0
[junit4:junit4] 2> 663761 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10054 (-1437950960742694912)]} 0 0
[junit4:junit4] 2> 663762 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[54 (-1437950960743743488)]} 0 0
[junit4:junit4] 2> 663763 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10054 (-1437950960744792064)]} 0 0
[junit4:junit4] 2> 663764 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[54 (-1437950960745840640)]} 0 0
[junit4:junit4] 2> 663768 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10057 (1437950960748986368)]} 0 1
[junit4:junit4] 2> 663768 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[57 (1437950960748986369)]} 0 1
[junit4:junit4] 2> 663770 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[57 (1437950960751083520)]} 0 1
[junit4:junit4] 2> 663770 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10057 (1437950960752132096)]} 0 1
[junit4:junit4] 2> 663797 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[58 (1437950960779395072)]} 0 1
[junit4:junit4] 2> 663797 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10058 (1437950960780443648)]} 0 0
[junit4:junit4] 2> 663800 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[58 (1437950960783589376)]} 0 0
[junit4:junit4] 2> 663800 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10058 (1437950960783589377)]} 0 0
[junit4:junit4] 2> 663844 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[59 (1437950960828678144)]} 0 1
[junit4:junit4] 2> 663845 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10059 (1437950960829726720)]} 0 1
[junit4:junit4] 2> 663847 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[59 (1437950960831823872)]} 0 1
[junit4:junit4] 2> 663848 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10059 (1437950960832872448)]} 0 1
[junit4:junit4] 2> 663881 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[60 (1437950960867475456)]} 0 1
[junit4:junit4] 2> 663882 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10060 (1437950960868524032)]} 0 1
[junit4:junit4] 2> 663883 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[60 (1437950960870621184)]} 0 0
[junit4:junit4] 2> 663884 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10060 (1437950960871669760)]} 0 0
[junit4:junit4] 2> 663897 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[58 (-1437950960885301248)]} 0 0
[junit4:junit4] 2> 663899 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10058 (-1437950960887398400)]} 0 0
[junit4:junit4] 2> 663900 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[58 (-1437950960888446976)]} 0 0
[junit4:junit4] 2> 663902 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10058 (-1437950960890544128)]} 0 0
[junit4:junit4] 2> 663903 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[61 (1437950960891592704)]} 0 0
[junit4:junit4] 2> 663904 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10061 (1437950960892641280)]} 0 0
[junit4:junit4] 2> 663907 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[61 (1437950960894738432)]} 0 1
[junit4:junit4] 2> 663908 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10061 (1437950960895787008)]} 0 1
[junit4:junit4] 2> 663934 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[59 (-1437950960924098560)]} 0 0
[junit4:junit4] 2> 663935 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10059 (-1437950960925147136)]} 0 0
[junit4:junit4] 2> 663936 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[59 (-1437950960926195712)]} 0 0
[junit4:junit4] 2> 663937 T980 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10059 (-1437950960927244288)]} 0 0
[junit4:junit4] 2> 663940 T958 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[62 (1437950960929341440)]} 0 1
[junit4:junit4] 2> 663940 T957 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10062 (1437950960930390016)]} 0 0
[junit4:junit4] 2> 663942 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[62 (1437950960931438592)]} 0 1
[junit4:junit4] 2> 663943 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10062 (1437950960932487168)]} 0 1
[junit4:junit4] 2> 663961 T959 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[60 (-1437950960952410112)]} 0 1
[junit4:junit4] 2> 663961 T961 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10060 (-1437950960952410113)]} 0 0
[junit4:junit4] 2> C3411_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51221_he%2Fhz, base_url=http://127.0.0.1:51221/he/hz}
[junit4:junit4] 2> 663964 T1004 C3411 P51221 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51212/he/hz/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 663964 T978 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10060 (-1437950960955555841)]} 0 0
[junit4:junit4] 2> 663964 T979 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[60 (-1437950960955555840)]} 0 0
[junit4:junit4] 2> 663965 T1004 C3411 P51221 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51221/he/hz START replicas=[http://127.0.0.1:51212/he/hz/collection1/] nUpdates=100
[junit4:junit4] 2> 663968 T960 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10063 (1437950960958701568)]} 0 1
[junit4:junit4] 2> 663969 T954 C3413 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[63 (1437950960959750144)]} 0 1
[junit4:junit4] 2> 663971 T976 C3412 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 663970 T1004 C3411 P51221 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 663973 T1004 C3411 P51221 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 663973 T1004 C3411 P51221 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 663973 T1004 C3411 P51221 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 663974 T1004 C3411 P51221 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\jetty2\tlog\tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 663974 T1004 C3411 P51221 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51212/he/hz/collection1/. core=collection1
[junit4:junit4] 2> 663975 T1004 C3411 P51221 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 663973 T976 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10063 (1437950960964993024)]} 0 1
[junit4:junit4] 2> 663981 T981 C3412 P51212 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 663974 T977 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[63 (1437950960966041600)]} 0 0
[junit4:junit4] 2> 664001 T981 C3412 P51212 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab2b774 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8eec016),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab2b774 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8eec016),segFN=segments_2,generation=2}
[junit4:junit4] 2> 664001 T981 C3412 P51212 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 664003 T981 C3412 P51212 oass.SolrIndexSearcher.<init> Opening Searcher@6dfd0e6c realtime
[junit4:junit4] 2> 664004 T981 C3412 P51212 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 664004 T981 C3412 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 664005 T1004 C3411 P51221 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 664005 T1004 C3411 P51221 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 664010 T978 C3412 P51212 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 664010 T978 C3412 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 664011 T1004 C3411 P51221 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 664011 T1004 C3411 P51221 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 664011 T1004 C3411 P51221 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 664012 T979 C3412 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 664013 T1004 C3411 P51221 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 5
[junit4:junit4] 2> 664014 T1004 C3411 P51221 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index.20130615235459764
[junit4:junit4] 2> 664014 T1004 C3411 P51221 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@615539d1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@420904ce) fullCopy=false
[junit4:junit4] 2> ASYNC NEW_CORE C3414 name=collection1 org.apache.solr.core.SolrCore@3fd6e06 url=http://127.0.0.1:51212/he/hz/collection1 node=127.0.0.1:51212_he%2Fhz C3414_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51212_he%2Fhz, base_url=http://127.0.0.1:51212/he/hz, leader=true}
[junit4:junit4] 2> 664096 T980 C3414 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={file=_0.cfs&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 664102 T980 C3414 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={file=_0.cfe&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 664127 T977 C3414 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> ASYNC NEW_CORE C3415 name=collection1 org.apache.solr.core.SolrCore@504bdd92 url=http://127.0.0.1:51200/he/hz/collection1 node=127.0.0.1:51200_he%2Fhz C3415_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51200_he%2Fhz, base_url=http://127.0.0.1:51200/he/hz, leader=true}
[junit4:junit4] 2> 664161 T958 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[64 (1437950961161076736)]} 0 1
[junit4:junit4] 2> 664163 T958 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10064 (1437950961163173888)]} 0 1
[junit4:junit4] 2> 664167 T978 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[64 (1437950961166319616)]} 0 2
[junit4:junit4] 2> 664171 T981 C3414 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=6
[junit4:junit4] 2> 664175 T980 C3414 P51212 oasc.SolrCore.execute [collection1] webapp=/he/hz path=/replication params={file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C3416 name=collection1 org.apache.solr.core.SolrCore@6757b12 url=http://127.0.0.1:51221/he/hz/collection1 node=127.0.0.1:51221_he%2Fhz C3416_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51221_he%2Fhz, base_url=http://127.0.0.1:51221/he/hz}
[junit4:junit4] 2> 664176 T1004 C3416 P51221 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 664178 T1004 C3416 P51221 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 664178 T1004 C3416 P51221 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 664178 T1004 C3416 P51221 oasu.DefaultSolrCoreState.newIndexWriter Closing old IndexWriter... core=collection1
[junit4:junit4] 2> 664178 T979 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10064 (1437950961170513920)]} 0 9
[junit4:junit4] 2> 664217 T1004 C3416 P51221 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 664217 T1004 C3416 P51221 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 664223 T1004 C3416 P51221 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 664223 T1004 C3416 P51221 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 664223 T1004 C3416 P51221 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 664223 T1004 C3416 P51221 oass.SolrIndexSearcher.<init> Opening Searcher@4563d1b2 main
[junit4:junit4] 2> 664224 T959 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10061 (-1437950961228185600)]} 0 0
[junit4:junit4] 2> 664225 T959 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[61 (-1437950961229234176)]} 0 0
[junit4:junit4] 2> 664227 T1003 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4563d1b2 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c40/14)}
[junit4:junit4] 2> 664228 T1004 C3416 P51221 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index.20130615235459764 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index.20130615235459764;done=true>>]
[junit4:junit4] 2> 664228 T1004 C3416 P51221 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index.20130615235459764
[junit4:junit4] 2> 664228 T1004 C3416 P51221 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index.20130615235459764
[junit4:junit4] 2> 664234 T977 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[61 (-1437950961238671360)]} 0 1
[junit4:junit4] 2> 664235 T1004 C3416 P51221 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 664235 T978 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10061 (-1437950961239719936)]} 0 0
[junit4:junit4] 2> 664236 T1012 C3416 P51221 oasu.UpdateLog$LogReplayer.doReplay WARN Starting log replay tlog{file=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\jetty2\tlog\tlog.0000000000000000000 refcount=2} active=true starting pos=5735
[junit4:junit4] 2> 664240 T1012 C3416 P51221 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 664243 T954 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10065 (1437950961248108544)]} 0 1
[junit4:junit4] 2> 664244 T958 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[65 (1437950961249157120)]} 0 0
[junit4:junit4] 2> 664245 T1012 C3416 P51221 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@726b8587 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24d0b7d0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 664245 T1012 C3416 P51221 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 664248 T976 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[65 (1437950961253351424)]} 0 1
[junit4:junit4] 2> 664249 T1012 C3416 P51221 oass.SolrIndexSearcher.<init> Opening Searcher@797b6241 main
[junit4:junit4] 2> 664249 T1012 C3416 P51221 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 664250 T1003 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@797b6241 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c40/14)}
[junit4:junit4] 2> 664251 T1012 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] {} 0 15
[junit4:junit4] 2> 664251 T1012 C3416 P51221 oasu.UpdateLog$LogReplayer.run WARN Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=5735}
[junit4:junit4] 2> 664251 T1004 C3416 P51221 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 664251 T1004 C3416 P51221 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 664251 T1004 C3416 P51221 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 664253 T981 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10065 (1437950961258594304)]} 0 1
[junit4:junit4] 2> 664258 T1004 C3416 P51221 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 664276 T957 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[66 (1437950961281662976)]} 0 1
[junit4:junit4] 2> 664280 T980 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[66 (1437950961286905856)]} 0 0
[junit4:junit4] 2> 664283 T961 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10066 (1437950961290051584)]} 0 0
[junit4:junit4] 2> 664287 T979 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10066 (1437950961294245888)]} 0 0
[junit4:junit4] 2> 664288 T959 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[67 (1437950961295294464)]} 0 0
[junit4:junit4] 2> 664292 T977 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[67 (1437950961299488768)]} 0 0
[junit4:junit4] 2> 664295 T960 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10067 (1437950961302634496)]} 0 0
[junit4:junit4] 2> 664300 T978 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10067 (1437950961307877376)]} 0 0
[junit4:junit4] 2> 664307 T954 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[64 (-1437950961315217408)]} 0 0
[junit4:junit4] 2> 664310 T976 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[64 (-1437950961318363136)]} 0 0
[junit4:junit4] 2> 664313 T958 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[68 (1437950961321508864)]} 0 0
[junit4:junit4] 2> 664316 T981 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[68 (1437950961323606016)]} 0 1
[junit4:junit4] 2> 664316 T957 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10064 (-1437950961324654592)]} 0 0
[junit4:junit4] 2> 664320 T980 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10064 (-1437950961328848896)]} 0 1
[junit4:junit4] 2> 664324 T961 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10068 (1437950961331994624)]} 0 1
[junit4:junit4] 2> 664328 T979 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10068 (1437950961337237504)]} 0 1
[junit4:junit4] 2> 664377 T959 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[66 (-1437950961388617728)]} 0 0
[junit4:junit4] 2> 664382 T977 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[66 (-1437950961393860608)]} 0 0
[junit4:junit4] 2> 664388 T960 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[69 (1437950961399103488)]} 0 1
[junit4:junit4] 2> 664392 T954 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10066 (-1437950961404346368)]} 0 0
[junit4:junit4] 2> 664393 T978 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[69 (1437950961404346368)]} 0 1
[junit4:junit4] 2> 664396 T976 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10066 (-1437950961408540672)]} 0 0
[junit4:junit4] 2> 664401 T958 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10069 (1437950961413783552)]} 0 0
[junit4:junit4] 2> 664407 T981 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10069 (1437950961419026432)]} 0 1
[junit4:junit4] 2> 664467 T957 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[68 (-1437950961481940992)]} 0 1
[junit4:junit4] 2> 664470 T980 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[68 (-1437950961486135296)]} 0 0
[junit4:junit4] 2> 664475 T961 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[70 (1437950961490329600)]} 0 1
[junit4:junit4] 2> 664479 T959 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10068 (-1437950961495572480)]} 0 0
[junit4:junit4] 2> 664479 T979 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[70 (1437950961495572480)]} 0 0
[junit4:junit4] 2> 664481 T966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 664481 T977 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10068 (-1437950961497669632)]} 0 0
[junit4:junit4] 2> 664482 T966 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51221_he%2Fhz_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:51221_he%2Fhz",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51221/he/hz"}
[junit4:junit4] 2> 664485 T960 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10070 (1437950961500815360)]} 0 1
[junit4:junit4] 2> 664488 T978 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10070 (1437950961503961088)]} 0 1
[junit4:junit4] 2> 664492 T972 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> 664492 T1001 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> 664492 T985 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> 664492 T965 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> 664540 T954 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[69 (-1437950961559535616)]} 0 1
[junit4:junit4] 2> C3416_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51221_he%2Fhz, base_url=http://127.0.0.1:51221/he/hz}
[junit4:junit4] 2> 664551 T993 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[69 (-1437950961566875648)]} 0 2
[junit4:junit4] 2> 664552 T976 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[69 (-1437950961566875648)]} 0 5
[junit4:junit4] 2> 664554 T957 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10069 (-1437950961574215680)]} 0 1
[junit4:junit4] 2> 664556 T961 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[71 (1437950961575264256)]} 0 1
[junit4:junit4] 2> 664560 T997 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10069 (-1437950961576312832)]} 0 1
[junit4:junit4] 2> 664561 T981 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {delete=[10069 (-1437950961576312832)]} 0 5
[junit4:junit4] 2> 664562 T995 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[71 (1437950961578409984)]} 0 2
[junit4:junit4] 2> 664563 T980 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[71 (1437950961578409984)]} 0 5
[junit4:junit4] 2> 664565 T959 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10071 (1437950961584701440)]} 0 1
[junit4:junit4] 2> 664570 T996 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10071 (1437950961586798592)]} 0 1
[junit4:junit4] 2> 664570 T977 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10071 (1437950961586798592)]} 0 4
[junit4:junit4] 2> 664613 T960 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[72 (1437950961636081664)]} 0 1
[junit4:junit4] 2> 664619 T992 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[72 (1437950961639227392)]} 0 0
[junit4:junit4] 2> 664620 T978 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[72 (1437950961639227392)]} 0 4
[junit4:junit4] 2> 664623 T958 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10072 (1437950961645518848)]} 0 1
[junit4:junit4] 2> 664628 T993 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10072 (1437950961648664576)]} 0 1
[junit4:junit4] 2> 664630 T976 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10072 (1437950961648664576)]} 0 5
[junit4:junit4] 2> 664631 T954 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[73 (1437950961654956032)]} 0 0
[junit4:junit4] 2> 664637 T997 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={distrib.from=http://127.0.0.1:51212/he/hz/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[73 (1437950961658101760)]} 0 0
[junit4:junit4] 2> 664638 T981 C3414 P51212 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[73 (1437950961658101760)]} 0 4
[junit4:junit4] 2> 664640 T957 C3415 P51200 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/update params={wt=javabin&version=2} {add=[10073 (1437950961664393216)]} 0 0
[junit4:junit4] 2> 664647 T995 C3416 P51221 oasup.LogUpdateProcessor.finish [collection1] webapp=/he/hz path=/
[...truncated too long message...]
der$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 749177 T965 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 749177 T965 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 750249 T943 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 750250 T943 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 750258 T943 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4a24d84a
[junit4:junit4] 2> 750276 T943 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=46,cumulative_deletesById=27,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 750278 T943 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 750279 T943 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 750281 T943 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 750292 T943 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 750293 T943 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 750294 T943 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\ [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\;done=false>>]
[junit4:junit4] 2> 750295 T943 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\
[junit4:junit4] 2> 750295 T943 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index;done=false>>]
[junit4:junit4] 2> 750297 T943 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.RecoveryZkTest-1371336882262/jetty2\index
[junit4:junit4] 2> 750299 T1037 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89871933916643338-127.0.0.1:51221_he%2Fhz-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 750324 T943 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/he/hz,null}
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\zookeeper\server1\data\version-2\log.1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\zookeeper\server1\data\version-2 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\zookeeper\server1\data FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\zookeeper\server1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1371336882262\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1371336882262 FAILED !!!!!
[junit4:junit4] 2> 750416 T943 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 750419 T943 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51193 51193
[junit4:junit4] 2> 750547 T985 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 753251 T985 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> 753253 T985 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 751943 T1025 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 753258 T1025 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> 753258 T1025 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[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=A0D53E6014E53113 -Dtests.slow=true -Dtests.locale=ja_JP -Dtests.timezone=GB -Dtests.file.encoding=Cp1252
[junit4:junit4] FAILURE 107s | RecoveryZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: expected:<200> but was:<35>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([A0D53E6014E53113:2133B07863BA512F]: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> 753364 T943 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=Asserting), text=PostingsFormat(name=Lucene41WithOrds), _version_=PostingsFormat(name=Asserting), rnd_b=PostingsFormat(name=SimpleText), intDefault=PostingsFormat(name=Asserting), timestamp=PostingsFormat(name=Asserting), id=PostingsFormat(name=SimpleText), a_t=PostingsFormat(name=Asserting), range_facet_sl=PostingsFormat(name=Lucene41WithOrds), range_facet_si=Pulsing41(freqCutoff=7 minBlockSize=95 maxBlockSize=214), other_tl1=PostingsFormat(name=Asserting), multiDefault=Pulsing41(freqCutoff=7 minBlockSize=95 maxBlockSize=214), a_si=Pulsing41(freqCutoff=7 minBlockSize=95 maxBlockSize=214)}, docValues:{timestamp=DocValuesFormat(name=CheapBastard)}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=ja_JP, timezone=GB
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=1,free=52656296,total=116674560
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestSolrDeletionPolicy2, TestDynamicFieldResource, CacheHeaderTest, TestPerFieldSimilarity, TestReloadAndDeleteDocs, PrimUtilsTest, TestRandomFaceting, TestClassNameShortening, CSVRequestHandlerTest, TestCopyFieldCollectionResource, OutputWriterTest, TestCollationField, QueryResultKeyTest, SearchHandlerTest, SpellPossibilityIteratorTest, PingRequestHandlerTest, ExternalFileFieldSortTest, TestSchemaResource, TestSurroundQueryParser, AliasIntegrationTest, DirectSolrSpellCheckerTest, TestPluginEnable, HighlighterConfigTest, NoCacheHeaderTest, TestBadConfig, PathHierarchyTokenizerFactoryTest, BadCopyFieldTest, TestCoreDiscovery, TestDefaultSearchFieldResource, DocValuesTest, ZkSolrClientTest, SpellCheckCollatorTest, TestSolrQueryParser, TestElisionMultitermQuery, TestRandomDVFaceting, ZkNodePropsTest, TestStressLucene, TestCSVResponseWriter, TestManagedSchemaFieldResource, UUIDFieldTest, StatsComponentTest, TestQuerySenderListener, FieldMutatingUpdateProcessorTest, TestSweetSpotSimilarityFactory, TermVectorComponentTest, TestQueryUtils, SyncSliceTest, TestMergePolicyConfig, TestSchemaVersionResource, OverseerCollectionProcessorTest, XsltUpdateRequestHandlerTest, FileBasedSpellCheckerTest, RecoveryZkTest]
[junit4:junit4] Completed in 106.89s, 1 test, 1 failure <<< FAILURES!
[...truncated 768 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:887: There were test failures: 296 suites, 1243 tests, 1 failure, 18 ignored (12 assumptions)
Total time: 76 minutes 23 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure