You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/25 13:58:45 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1357 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1357/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:34395/collection1lastClient and got 248 from http://127.0.0.1:34403/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:34395/collection1lastClient and got 248 from http://127.0.0.1:34403/collection1
at __randomizedtesting.SeedInfo.seed([1EF5BDA2D1848B85:9F1333BAA6DBEBB9]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9545 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 600261 T1750 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 600267 T1750 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1372160162361
[junit4:junit4] 2> 600269 T1750 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 600270 T1751 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 600371 T1750 oasc.ZkTestServer.run start zk server on port:34388
[junit4:junit4] 2> 600372 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 600401 T1757 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6730b844 name:ZooKeeperConnection Watcher:127.0.0.1:34388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 600401 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 600402 T1750 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 600418 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 600420 T1759 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cc0dce3 name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 600421 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 600421 T1750 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 600426 T1750 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 600434 T1750 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 600437 T1750 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 600440 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 600441 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 600447 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 600448 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 600551 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 600552 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 600555 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 600556 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 600565 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 600566 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 600569 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 600570 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 600573 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 600574 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 600577 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 600578 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 600581 T1750 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 600582 T1750 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 600859 T1750 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 600863 T1750 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34391
[junit4:junit4] 2> 600864 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 600864 T1750 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 600865 T1750 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684
[junit4:junit4] 2> 600865 T1750 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/solr.xml
[junit4:junit4] 2> 600866 T1750 oasc.CoreContainer.<init> New CoreContainer 873552802
[junit4:junit4] 2> 600866 T1750 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/'
[junit4:junit4] 2> 600867 T1750 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/'
[junit4:junit4] 2> 600995 T1750 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 600996 T1750 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 600996 T1750 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 600997 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 600998 T1750 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 600998 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 600998 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 600999 T1750 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 601000 T1750 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 601000 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 601018 T1750 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 601019 T1750 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:34388/solr
[junit4:junit4] 2> 601019 T1750 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 601020 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 601023 T1770 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b9df29 name:ZooKeeperConnection Watcher:127.0.0.1:34388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 601024 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 601034 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 601048 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 601051 T1772 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b869c8d name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 601052 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 601059 T1750 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 601063 T1750 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 601073 T1750 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 601075 T1750 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34391_
[junit4:junit4] 2> 601082 T1750 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34391_
[junit4:junit4] 2> 601085 T1750 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 601100 T1750 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 601103 T1750 oasc.Overseer.start Overseer (id=89925888400949251-127.0.0.1:34391_-n_0000000000) starting
[junit4:junit4] 2> 601113 T1750 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 601118 T1774 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 601119 T1750 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 601121 T1750 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 601128 T1750 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 601131 T1773 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 601134 T1775 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 601135 T1775 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 602634 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 602635 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34391_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34391"}
[junit4:junit4] 2> 602636 T1773 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 602636 T1773 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 602655 T1772 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> 603138 T1775 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/collection1
[junit4:junit4] 2> 603138 T1775 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 603139 T1775 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 603139 T1775 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 603141 T1775 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/collection1/'
[junit4:junit4] 2> 603142 T1775 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 603143 T1775 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/collection1/lib/README' to classloader
[junit4:junit4] 2> 603211 T1775 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 603271 T1775 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 603373 T1775 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 603379 T1775 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 603999 T1775 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 603999 T1775 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 604000 T1775 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 604008 T1775 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 604011 T1775 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 604023 T1775 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 604027 T1775 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 604030 T1775 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 604031 T1775 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 604032 T1775 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 604032 T1775 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 604033 T1775 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 604033 T1775 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 604033 T1775 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 604033 T1775 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372160162684/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/
[junit4:junit4] 2> 604034 T1775 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5e555139
[junit4:junit4] 2> 604034 T1775 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 604035 T1775 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data
[junit4:junit4] 2> 604036 T1775 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index/
[junit4:junit4] 2> 604036 T1775 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 604037 T1775 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index
[junit4:junit4] 2> 604043 T1775 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 604043 T1775 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 604045 T1775 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 604045 T1775 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 604046 T1775 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 604046 T1775 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 604047 T1775 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 604047 T1775 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 604047 T1775 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 604047 T1775 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 604048 T1775 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 604058 T1775 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 604065 T1775 oass.SolrIndexSearcher.<init> Opening Searcher@3781be98 main
[junit4:junit4] 2> 604065 T1775 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 604066 T1775 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 604068 T1776 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3781be98 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 604070 T1775 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 604070 T1775 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34391 collection:control_collection shard:shard1
[junit4:junit4] 2> 604071 T1775 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 604087 T1775 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 604099 T1775 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 604099 T1775 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 604099 T1775 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34391/collection1/
[junit4:junit4] 2> 604100 T1775 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 604100 T1775 oasc.SyncStrategy.syncToMe http://127.0.0.1:34391/collection1/ has no replicas
[junit4:junit4] 2> 604100 T1775 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34391/collection1/
[junit4:junit4] 2> 604100 T1775 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 604159 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 604176 T1772 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> 604218 T1775 oasc.ZkController.register We are http://127.0.0.1:34391/collection1/ and leader is http://127.0.0.1:34391/collection1/
[junit4:junit4] 2> 604218 T1775 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34391
[junit4:junit4] 2> 604218 T1775 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 604219 T1775 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 604219 T1775 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 604221 T1775 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 604222 T1750 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 604222 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 604223 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 604233 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 604234 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 604236 T1779 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@55b2b945 name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 604236 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 604238 T1750 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 604240 T1750 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 604508 T1750 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 604511 T1750 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34395
[junit4:junit4] 2> 604512 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 604512 T1750 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 604513 T1750 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332
[junit4:junit4] 2> 604513 T1750 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/solr.xml
[junit4:junit4] 2> 604514 T1750 oasc.CoreContainer.<init> New CoreContainer 1632589420
[junit4:junit4] 2> 604514 T1750 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/'
[junit4:junit4] 2> 604515 T1750 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/'
[junit4:junit4] 2> 604643 T1750 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 604644 T1750 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 604644 T1750 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 604645 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 604645 T1750 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 604646 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 604646 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 604647 T1750 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 604647 T1750 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 604648 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 604663 T1750 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 604664 T1750 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:34388/solr
[junit4:junit4] 2> 604665 T1750 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 604666 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 604669 T1790 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2323bf05 name:ZooKeeperConnection Watcher:127.0.0.1:34388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 604669 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 604679 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 604686 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 604688 T1792 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@454ae9e8 name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 604688 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 604698 T1750 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 605689 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 605690 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34391_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34391"}
[junit4:junit4] 2> 605702 T1772 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> 605702 T1750 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34395_
[junit4:junit4] 2> 605702 T1779 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> 605702 T1792 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> 605710 T1750 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34395_
[junit4:junit4] 2> 605713 T1779 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> 605714 T1772 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 605714 T1792 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 605714 T1772 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> 605714 T1792 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> 605715 T1779 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 605721 T1793 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 605722 T1793 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 607214 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 607215 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:34395_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34395"}
[junit4:junit4] 2> 607215 T1773 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 607215 T1773 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 607258 T1772 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> 607258 T1779 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> 607258 T1792 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> 607725 T1793 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/collection1
[junit4:junit4] 2> 607725 T1793 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 607726 T1793 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 607726 T1793 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 607825 T1793 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/collection1/'
[junit4:junit4] 2> 607826 T1793 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 607827 T1793 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/collection1/lib/README' to classloader
[junit4:junit4] 2> 607879 T1793 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 607939 T1793 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 608041 T1793 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 608045 T1793 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 608467 T1793 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 608468 T1793 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 608468 T1793 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 608476 T1793 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 608479 T1793 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 608492 T1793 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 608495 T1793 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 608499 T1793 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 608500 T1793 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 608500 T1793 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 608500 T1793 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 608501 T1793 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 608501 T1793 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 608501 T1793 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 608502 T1793 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372160166332/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/
[junit4:junit4] 2> 608502 T1793 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5e555139
[junit4:junit4] 2> 608502 T1793 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 608503 T1793 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1
[junit4:junit4] 2> 608504 T1793 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index/
[junit4:junit4] 2> 608504 T1793 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 608505 T1793 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index
[junit4:junit4] 2> 608510 T1793 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 608510 T1793 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 608513 T1793 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 608513 T1793 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 608513 T1793 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 608514 T1793 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 608514 T1793 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 608515 T1793 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 608515 T1793 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 608515 T1793 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 608516 T1793 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 608526 T1793 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 608532 T1793 oass.SolrIndexSearcher.<init> Opening Searcher@39a3d16f main
[junit4:junit4] 2> 608533 T1793 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 608534 T1793 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 608537 T1794 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@39a3d16f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 608538 T1793 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 608539 T1793 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34395 collection:collection1 shard:shard1
[junit4:junit4] 2> 608539 T1793 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 608547 T1793 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 608559 T1793 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 608559 T1793 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 608559 T1793 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 608560 T1793 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 608560 T1793 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/ has no replicas
[junit4:junit4] 2> 608560 T1793 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 608560 T1793 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 608762 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 608778 T1772 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> 608778 T1792 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> 608778 T1779 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> 608831 T1793 oasc.ZkController.register We are http://127.0.0.1:34395/collection1/ and leader is http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 608831 T1793 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34395
[junit4:junit4] 2> 608831 T1793 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 608831 T1793 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 608832 T1793 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 608834 T1793 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 608835 T1750 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 608835 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 608836 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 609025 T1750 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 609028 T1750 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34399
[junit4:junit4] 2> 609028 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 609029 T1750 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 609029 T1750 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939
[junit4:junit4] 2> 609030 T1750 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/solr.xml
[junit4:junit4] 2> 609030 T1750 oasc.CoreContainer.<init> New CoreContainer 1577512222
[junit4:junit4] 2> 609030 T1750 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/'
[junit4:junit4] 2> 609031 T1750 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/'
[junit4:junit4] 2> 609115 T1750 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 609116 T1750 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 609116 T1750 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 609117 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 609117 T1750 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 609117 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 609117 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 609118 T1750 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 609118 T1750 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 609119 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 609130 T1750 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 609130 T1750 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:34388/solr
[junit4:junit4] 2> 609131 T1750 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 609132 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 609134 T1806 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d2e6374 name:ZooKeeperConnection Watcher:127.0.0.1:34388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 609135 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 609146 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 609159 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 609161 T1808 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11c6fb2e name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 609162 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 609167 T1750 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 610170 T1750 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34399_
[junit4:junit4] 2> 610172 T1750 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34399_
[junit4:junit4] 2> 610227 T1779 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> 610228 T1792 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 610228 T1808 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 610228 T1792 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> 610228 T1772 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 610229 T1772 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> 610229 T1779 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 610288 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 610289 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:34395_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34395"}
[junit4:junit4] 2> 610290 T1809 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 610290 T1809 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 610360 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:34399_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34399"}
[junit4:junit4] 2> 610360 T1773 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 610361 T1773 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 610378 T1772 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> 610378 T1779 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> 610378 T1792 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> 610378 T1808 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> 611309 T1809 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/collection1
[junit4:junit4] 2> 611309 T1809 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 611310 T1809 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 611310 T1809 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 611312 T1809 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/collection1/'
[junit4:junit4] 2> 611314 T1809 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/collection1/lib/README' to classloader
[junit4:junit4] 2> 611314 T1809 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 611371 T1809 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 611441 T1809 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 611543 T1809 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 611549 T1809 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 612182 T1809 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 612183 T1809 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 612184 T1809 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 612196 T1809 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 612200 T1809 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 612216 T1809 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 612221 T1809 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 612225 T1809 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 612226 T1809 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 612226 T1809 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 612227 T1809 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 612228 T1809 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 612228 T1809 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 612228 T1809 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 612229 T1809 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372160170939/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/
[junit4:junit4] 2> 612229 T1809 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5e555139
[junit4:junit4] 2> 612230 T1809 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 612231 T1809 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2
[junit4:junit4] 2> 612232 T1809 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index/
[junit4:junit4] 2> 612233 T1809 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 612233 T1809 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index
[junit4:junit4] 2> 612241 T1809 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 612241 T1809 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 612244 T1809 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 612245 T1809 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 612245 T1809 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 612246 T1809 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 612247 T1809 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 612247 T1809 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 612247 T1809 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 612248 T1809 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 612249 T1809 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 612265 T1809 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 612274 T1809 oass.SolrIndexSearcher.<init> Opening Searcher@6f40017b main
[junit4:junit4] 2> 612276 T1809 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 612276 T1809 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 612281 T1810 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6f40017b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 612283 T1809 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 612283 T1809 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34399 collection:collection1 shard:shard1
[junit4:junit4] 2> 612287 T1809 oasc.ZkController.register We are http://127.0.0.1:34399/collection1/ and leader is http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 612287 T1809 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34399
[junit4:junit4] 2> 612287 T1809 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 612287 T1809 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C358 name=collection1 org.apache.solr.core.SolrCore@405e6417 url=http://127.0.0.1:34399/collection1 node=127.0.0.1:34399_ C358_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:34399_, base_url=http://127.0.0.1:34399}
[junit4:junit4] 2> 612288 T1811 C358 P34399 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 612288 T1811 C358 P34399 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 612288 T1809 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 612289 T1811 C358 P34399 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 612289 T1811 C358 P34399 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 612290 T1750 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 612290 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 612290 T1811 C358 P34399 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 612291 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 612312 T1782 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 612581 T1750 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 612584 T1750 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34403
[junit4:junit4] 2> 612584 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 612585 T1750 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 612585 T1750 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403
[junit4:junit4] 2> 612586 T1750 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/solr.xml
[junit4:junit4] 2> 612586 T1750 oasc.CoreContainer.<init> New CoreContainer 1839268005
[junit4:junit4] 2> 612587 T1750 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/'
[junit4:junit4] 2> 612588 T1750 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/'
[junit4:junit4] 2> 612717 T1750 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 612718 T1750 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 612719 T1750 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 612719 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 612720 T1750 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 612720 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 612721 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 612721 T1750 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 612722 T1750 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 612722 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 612740 T1750 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 612741 T1750 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:34388/solr
[junit4:junit4] 2> 612741 T1750 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 612742 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 612745 T1823 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37f74e14 name:ZooKeeperConnection Watcher:127.0.0.1:34388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 612746 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 612761 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 612773 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 612775 T1825 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c5e1e09 name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 612776 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 612787 T1750 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 613394 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 613395 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:34399_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34399"}
[junit4:junit4] 2> 613410 T1772 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> 613410 T1825 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> 613410 T1779 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> 613410 T1792 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> 613410 T1808 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> 613790 T1750 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34403_
[junit4:junit4] 2> 613828 T1750 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34403_
[junit4:junit4] 2> 613830 T1808 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> 613830 T1825 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> 613831 T1772 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613830 T1779 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> 613831 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 613831 T1792 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613832 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 613832 T1808 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613832 T1825 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613833 T1779 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613838 T1826 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 613839 T1826 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 614314 T1782 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 614314 T1782 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:34399_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 614915 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 614917 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:34403_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34403"}
[junit4:junit4] 2> 614917 T1773 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 614917 T1773 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 615011 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 615012 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 615012 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 615012 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 615012 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 615842 T1826 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/collection1
[junit4:junit4] 2> 615842 T1826 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 615843 T1826 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 615843 T1826 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 615845 T1826 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/collection1/'
[junit4:junit4] 2> 615846 T1826 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 615847 T1826 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/collection1/lib/README' to classloader
[junit4:junit4] 2> 615899 T1826 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 615960 T1826 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 616061 T1826 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 616067 T1826 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C359 name=collection1 org.apache.solr.core.SolrCore@405e6417 url=http://127.0.0.1:34399/collection1 node=127.0.0.1:34399_ C359_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:34399_, base_url=http://127.0.0.1:34399}
[junit4:junit4] 2> 616316 T1811 C359 P34399 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:34395/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 616316 T1811 C359 P34399 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34399 START replicas=[http://127.0.0.1:34395/collection1/] nUpdates=100
[junit4:junit4] 2> 616317 T1811 C359 P34399 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 616318 T1811 C359 P34399 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 616318 T1811 C359 P34399 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 616318 T1811 C359 P34399 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 616318 T1811 C359 P34399 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 616319 T1811 C359 P34399 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:34395/collection1/. core=collection1
[junit4:junit4] 2> 616319 T1811 C359 P34399 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C360 name=collection1 org.apache.solr.core.SolrCore@52f16e9b url=http://127.0.0.1:34395/collection1 node=127.0.0.1:34395_ C360_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34395_, base_url=http://127.0.0.1:34395, leader=true}
[junit4:junit4] 2> 616327 T1783 C360 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 616331 T1784 C360 P34395 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 616336 T1784 C360 P34395 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 616337 T1784 C360 P34395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 616342 T1784 C360 P34395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 616343 T1784 C360 P34395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 616344 T1784 C360 P34395 oass.SolrIndexSearcher.<init> Opening Searcher@211ee911 realtime
[junit4:junit4] 2> 616345 T1784 C360 P34395 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 616345 T1784 C360 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 15
[junit4:junit4] 2> 616346 T1811 C359 P34399 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 616346 T1811 C359 P34399 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 616349 T1785 C360 P34395 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 616349 T1785 C360 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 616350 T1811 C359 P34399 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 616350 T1811 C359 P34399 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 616350 T1811 C359 P34399 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 616352 T1785 C360 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 616353 T1811 C359 P34399 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 616354 T1811 C359 P34399 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index.20130625170618445
[junit4:junit4] 2> 616356 T1811 C359 P34399 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index.20130625170618445 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19fd5590; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 616359 T1785 C360 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 616361 T1811 C359 P34399 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 616364 T1811 C359 P34399 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 616364 T1811 C359 P34399 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 616370 T1811 C359 P34399 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 616371 T1811 C359 P34399 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 616371 T1811 C359 P34399 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 616373 T1811 C359 P34399 oass.SolrIndexSearcher.<init> Opening Searcher@3f1269 main
[junit4:junit4] 2> 616374 T1810 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f1269 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 616374 T1811 C359 P34399 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index.20130625170618445 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index.20130625170618445;done=true>>]
[junit4:junit4] 2> 616375 T1811 C359 P34399 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index.20130625170618445
[junit4:junit4] 2> 616375 T1811 C359 P34399 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index.20130625170618445
[junit4:junit4] 2> 616377 T1811 C359 P34399 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 616377 T1811 C359 P34399 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 616377 T1811 C359 P34399 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 616377 T1811 C359 P34399 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 616379 T1811 C359 P34399 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 616570 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 616571 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:34399_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34399"}
[junit4:junit4] 2> 616585 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 616585 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 616585 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 616585 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 616585 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 616714 T1826 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 616715 T1826 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 616716 T1826 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 616728 T1826 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 616732 T1826 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 616747 T1826 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 616767 T1826 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 616771 T1826 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 616772 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 616773 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 616773 T1826 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 616774 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 616774 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 616774 T1826 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 616775 T1826 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372160174403/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/
[junit4:junit4] 2> 616775 T1826 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5e555139
[junit4:junit4] 2> 616776 T1826 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 616777 T1826 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3
[junit4:junit4] 2> 616778 T1826 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index/
[junit4:junit4] 2> 616779 T1826 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 616779 T1826 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index
[junit4:junit4] 2> 616787 T1826 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 616787 T1826 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 616790 T1826 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 616791 T1826 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 616792 T1826 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 616792 T1826 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 616793 T1826 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 616793 T1826 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 616797 T1826 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 616797 T1826 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 616798 T1826 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 616814 T1826 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 616824 T1826 oass.SolrIndexSearcher.<init> Opening Searcher@107667ca main
[junit4:junit4] 2> 616825 T1826 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 616825 T1826 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 616830 T1829 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@107667ca main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 616832 T1826 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 616832 T1826 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34403 collection:collection1 shard:shard1
[junit4:junit4] 2> 616835 T1826 oasc.ZkController.register We are http://127.0.0.1:34403/collection1/ and leader is http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 616836 T1826 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34403
[junit4:junit4] 2> 616836 T1826 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 616836 T1826 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C361 name=collection1 org.apache.solr.core.SolrCore@51779b6f url=http://127.0.0.1:34403/collection1 node=127.0.0.1:34403_ C361_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:34403_, base_url=http://127.0.0.1:34403}
[junit4:junit4] 2> 616837 T1830 C361 P34403 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 616837 T1830 C361 P34403 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 616837 T1826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 616837 T1830 C361 P34403 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 616838 T1830 C361 P34403 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 616839 T1750 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 616839 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 616839 T1830 C361 P34403 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 616840 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 616859 T1786 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 617152 T1750 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 617155 T1750 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34410
[junit4:junit4] 2> 617156 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 617157 T1750 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 617157 T1750 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950
[junit4:junit4] 2> 617158 T1750 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/solr.xml
[junit4:junit4] 2> 617158 T1750 oasc.CoreContainer.<init> New CoreContainer 1530614352
[junit4:junit4] 2> 617159 T1750 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/'
[junit4:junit4] 2> 617159 T1750 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/'
[junit4:junit4] 2> 617289 T1750 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 617290 T1750 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 617290 T1750 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 617291 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 617291 T1750 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 617292 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 617292 T1750 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 617293 T1750 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 617293 T1750 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 617294 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 617310 T1750 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 617311 T1750 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:34388/solr
[junit4:junit4] 2> 617311 T1750 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 617312 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 617316 T1842 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a3cb04c name:ZooKeeperConnection Watcher:127.0.0.1:34388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 617316 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 617328 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 617338 T1750 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 617340 T1844 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@667813d9 name:ZooKeeperConnection Watcher:127.0.0.1:34388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 617341 T1750 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 617353 T1750 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 618090 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 618090 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:34403_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34403"}
[junit4:junit4] 2> 618103 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618103 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618104 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618103 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618103 T1844 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618103 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618356 T1750 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34410_
[junit4:junit4] 2> 618358 T1750 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34410_
[junit4:junit4] 2> 618361 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618361 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618361 T1772 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 618361 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 618361 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 618361 T1792 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 618361 T1844 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 618362 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 618362 T1808 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 618362 T1844 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 618363 T1825 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 618371 T1779 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 618376 T1845 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 618376 T1845 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 618862 T1786 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 618862 T1786 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:34403_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 619608 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 619609 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:34410_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34410"}
[junit4:junit4] 2> 619610 T1773 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 619610 T1773 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 619626 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 619626 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 619626 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 619626 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 619626 T1844 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 619626 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 620379 T1845 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/collection1
[junit4:junit4] 2> 620379 T1845 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 620380 T1845 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 620380 T1845 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 620382 T1845 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/collection1/'
[junit4:junit4] 2> 620383 T1845 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/collection1/lib/README' to classloader
[junit4:junit4] 2> 620384 T1845 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 620436 T1845 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 620496 T1845 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 620598 T1845 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 620604 T1845 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C362 name=collection1 org.apache.solr.core.SolrCore@51779b6f url=http://127.0.0.1:34403/collection1 node=127.0.0.1:34403_ C362_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:34403_, base_url=http://127.0.0.1:34403}
[junit4:junit4] 2> 620864 T1830 C362 P34403 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:34395/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 620864 T1830 C362 P34403 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34403 START replicas=[http://127.0.0.1:34395/collection1/] nUpdates=100
[junit4:junit4] 2> 620865 T1830 C362 P34403 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 620865 T1830 C362 P34403 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 620865 T1830 C362 P34403 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 620865 T1830 C362 P34403 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 620865 T1830 C362 P34403 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 620866 T1830 C362 P34403 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:34395/collection1/. core=collection1
[junit4:junit4] 2> 620866 T1830 C362 P34403 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C363 name=collection1 org.apache.solr.core.SolrCore@52f16e9b url=http://127.0.0.1:34395/collection1 node=127.0.0.1:34395_ C363_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34395_, base_url=http://127.0.0.1:34395, leader=true}
[junit4:junit4] 2> 620867 T1783 C363 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 620879 T1787 C363 P34395 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 620885 T1787 C363 P34395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 620886 T1787 C363 P34395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 620887 T1787 C363 P34395 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 620888 T1787 C363 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 620889 T1830 C362 P34403 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 620889 T1830 C362 P34403 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 620891 T1785 C363 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 620892 T1830 C362 P34403 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 620892 T1830 C362 P34403 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 620892 T1830 C362 P34403 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 620895 T1785 C363 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 620896 T1830 C362 P34403 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 620898 T1830 C362 P34403 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index.20130625170622988
[junit4:junit4] 2> 620899 T1830 C362 P34403 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index.20130625170622988 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f96eede; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 620903 T1785 C363 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 620905 T1830 C362 P34403 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 620908 T1830 C362 P34403 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 620908 T1830 C362 P34403 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 620914 T1830 C362 P34403 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 620915 T1830 C362 P34403 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 620915 T1830 C362 P34403 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 620917 T1830 C362 P34403 oass.SolrIndexSearcher.<init> Opening Searcher@442f4cca main
[junit4:junit4] 2> 620918 T1829 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@442f4cca main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 620918 T1830 C362 P34403 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index.20130625170622988 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index.20130625170622988;done=true>>]
[junit4:junit4] 2> 620919 T1830 C362 P34403 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index.20130625170622988
[junit4:junit4] 2> 620919 T1830 C362 P34403 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index.20130625170622988
[junit4:junit4] 2> 620920 T1830 C362 P34403 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 620921 T1830 C362 P34403 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 620921 T1830 C362 P34403 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 620921 T1830 C362 P34403 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 620923 T1830 C362 P34403 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 621131 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 621131 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:34403_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34403"}
[junit4:junit4] 2> 621136 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 621136 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 621136 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 621136 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 621136 T1844 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 621136 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 621247 T1845 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 621248 T1845 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 621249 T1845 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 621261 T1845 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 621265 T1845 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 621280 T1845 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 621300 T1845 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 621304 T1845 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 621305 T1845 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 621306 T1845 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 621306 T1845 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 621307 T1845 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 621307 T1845 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 621308 T1845 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 621308 T1845 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372160178950/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/
[junit4:junit4] 2> 621309 T1845 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5e555139
[junit4:junit4] 2> 621309 T1845 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 621310 T1845 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4
[junit4:junit4] 2> 621311 T1845 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index/
[junit4:junit4] 2> 621312 T1845 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 621313 T1845 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index
[junit4:junit4] 2> 621320 T1845 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 621320 T1845 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 621323 T1845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 621324 T1845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 621325 T1845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 621325 T1845 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 621326 T1845 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 621326 T1845 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 621330 T1845 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 621330 T1845 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 621331 T1845 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 621347 T1845 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 621357 T1845 oass.SolrIndexSearcher.<init> Opening Searcher@6d9ca028 main
[junit4:junit4] 2> 621358 T1845 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 621358 T1845 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 621363 T1848 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6d9ca028 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 621365 T1845 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 621366 T1845 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34410 collection:collection1 shard:shard1
[junit4:junit4] 2> 621369 T1845 oasc.ZkController.register We are http://127.0.0.1:34410/collection1/ and leader is http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 621369 T1845 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34410
[junit4:junit4] 2> 621369 T1845 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 621370 T1845 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C364 name=collection1 org.apache.solr.core.SolrCore@5e1e2724 url=http://127.0.0.1:34410/collection1 node=127.0.0.1:34410_ C364_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:34410_, base_url=http://127.0.0.1:34410}
[junit4:junit4] 2> 621370 T1849 C364 P34410 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 621371 T1845 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 621371 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 621371 T1849 C364 P34410 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 621371 T1849 C364 P34410 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 621372 T1750 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 621373 T1750 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 621373 T1849 C364 P34410 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 621373 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 621394 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 621394 T1788 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 621395 T1750 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 621395 T1750 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 621396 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 622398 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 622647 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 622648 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:34410_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34410"}
[junit4:junit4] 2> 622695 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 622695 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 622695 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 622695 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 622695 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 622695 T1844 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 623397 T1788 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 623397 T1788 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:34410_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 623401 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624403 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C364_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:34410_, base_url=http://127.0.0.1:34410}
[junit4:junit4] 2> 625399 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:34395/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 625399 T1849 C364 P34410 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34410 START replicas=[http://127.0.0.1:34395/collection1/] nUpdates=100
[junit4:junit4] 2> 625400 T1849 C364 P34410 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 625400 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 625400 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 625400 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 625400 T1849 C364 P34410 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 625401 T1849 C364 P34410 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:34395/collection1/. core=collection1
[junit4:junit4] 2> 625401 T1849 C364 P34410 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C365 name=collection1 org.apache.solr.core.SolrCore@52f16e9b url=http://127.0.0.1:34395/collection1 node=127.0.0.1:34395_ C365_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34395_, base_url=http://127.0.0.1:34395, leader=true}
[junit4:junit4] 2> 625402 T1783 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 625405 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625412 T1782 C365 P34395 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625417 T1782 C365 P34395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 625418 T1782 C365 P34395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 625419 T1782 C365 P34395 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625419 T1782 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 625420 T1849 C364 P34410 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 625420 T1849 C364 P34410 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 625423 T1785 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 625424 T1849 C364 P34410 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 625424 T1849 C364 P34410 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 625424 T1849 C364 P34410 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 625428 T1785 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 625428 T1849 C364 P34410 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 625430 T1849 C364 P34410 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index.20130625170627521
[junit4:junit4] 2> 625431 T1849 C364 P34410 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index.20130625170627521 lockFactory=org.apache.lucene.store.NativeFSLockFactory@75ce3f55; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 625435 T1785 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 625437 T1849 C364 P34410 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 625439 T1849 C364 P34410 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 625439 T1849 C364 P34410 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 625444 T1849 C364 P34410 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 625445 T1849 C364 P34410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 625445 T1849 C364 P34410 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 625446 T1849 C364 P34410 oass.SolrIndexSearcher.<init> Opening Searcher@340a3fa8 main
[junit4:junit4] 2> 625447 T1848 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@340a3fa8 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 625448 T1849 C364 P34410 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index.20130625170627521 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index.20130625170627521;done=true>>]
[junit4:junit4] 2> 625448 T1849 C364 P34410 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index.20130625170627521
[junit4:junit4] 2> 625449 T1849 C364 P34410 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index.20130625170627521
[junit4:junit4] 2> 625450 T1849 C364 P34410 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 625450 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 625450 T1849 C364 P34410 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 625450 T1849 C364 P34410 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 625452 T1849 C364 P34410 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 625702 T1773 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625703 T1773 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:34410_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34410"}
[junit4:junit4] 2> 625720 T1772 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 625720 T1825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 625720 T1844 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 625720 T1779 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 625720 T1792 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 625720 T1808 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 626407 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 626408 T1750 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C366 name=collection1 org.apache.solr.core.SolrCore@1c705fab url=http://127.0.0.1:34391/collection1 node=127.0.0.1:34391_ C366_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:34391_, base_url=http://127.0.0.1:34391, leader=true}
[junit4:junit4] 2> 626421 T1762 C366 P34391 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 626427 T1762 C366 P34391 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 626428 T1762 C366 P34391 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 626460 T1762 C366 P34391 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 626461 T1762 C366 P34391 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 626463 T1762 C366 P34391 oass.SolrIndexSearcher.<init> Opening Searcher@304269 main
[junit4:junit4] 2> 626464 T1762 C366 P34391 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 626465 T1776 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@304269 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 626465 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 44
[junit4:junit4] 2> 626477 T1784 C365 P34395 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:34395/collection1/, StdNode: http://127.0.0.1:34399/collection1/, StdNode: http://127.0.0.1:34403/collection1/, StdNode: http://127.0.0.1:34410/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 626480 T1786 C365 P34395 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 626486 T1786 C365 P34395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 626487 T1786 C365 P34395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 626489 T1786 C365 P34395 oass.SolrIndexSearcher.<init> Opening Searcher@61848fc main
[junit4:junit4] 2> 626490 T1786 C365 P34395 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 626491 T1794 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@61848fc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 626491 T1786 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> C364_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34410_, base_url=http://127.0.0.1:34410}
[junit4:junit4] 2> 626501 T1834 C364 P34410 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C367 name=collection1 org.apache.solr.core.SolrCore@405e6417 url=http://127.0.0.1:34399/collection1 node=127.0.0.1:34399_ C367_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34399_, base_url=http://127.0.0.1:34399}
[junit4:junit4] 2> 626502 T1798 C367 P34399 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C368 name=collection1 org.apache.solr.core.SolrCore@51779b6f url=http://127.0.0.1:34403/collection1 node=127.0.0.1:34403_ C368_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34403_, base_url=http://127.0.0.1:34403}
[junit4:junit4] 2> 626501 T1815 C368 P34403 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 626517 T1834 C364 P34410 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 626517 T1798 C367 P34399 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 626518 T1834 C364 P34410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 626518 T1798 C367 P34399 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 626520 T1815 C368 P34403 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 626521 T1815 C368 P34403 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 626521 T1834 C364 P34410 oass.SolrIndexSearcher.<init> Opening Searcher@dbf5501 main
[junit4:junit4] 2> 626522 T1798 C367 P34399 oass.SolrIndexSearcher.<init> Opening Searcher@6b062cc7 main
[junit4:junit4] 2> 626522 T1834 C364 P34410 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 626522 T1798 C367 P34399 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 626523 T1815 C368 P34403 oass.SolrIndexSearcher.<init> Opening Searcher@1363228b main
[junit4:junit4] 2> 626523 T1848 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dbf5501 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 626524 T1815 C368 P34403 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 626523 T1810 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6b062cc7 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 626524 T1834 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 626525 T1798 C367 P34399 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 626524 T1829 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1363228b main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 626526 T1815 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 626526 T1784 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 49
[junit4:junit4] 2> 626528 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 626531 T1787 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 626533 T1799 C367 P34399 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 626535 T1816 C368 P34403 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 626537 T1835 C364 P34410 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 628544 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438814244054237184)} 0 3
[junit4:junit4] 2> 628553 T1815 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438814244059480064&update.from=http://127.0.0.1:34395/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438814244059480064)} 0 2
[junit4:junit4] 2> 628554 T1834 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438814244059480064&update.from=http://127.0.0.1:34395/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438814244059480064)} 0 3
[junit4:junit4] 2> 628554 T1798 C367 P34399 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438814244059480064&update.from=http://127.0.0.1:34395/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438814244059480064)} 0 3
[junit4:junit4] 2> 628555 T1784 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438814244059480064)} 0 8
[junit4:junit4] 2> 628561 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438814244071014400)]} 0 3
[junit4:junit4] 2> 628572 T1798 C367 P34399 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438814244077305856)]} 0 3
[junit4:junit4] 2> 628573 T1834 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438814244077305856)]} 0 4
[junit4:junit4] 2> 628573 T1815 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438814244077305856)]} 0 4
[junit4:junit4] 2> 628574 T1784 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438814244077305856)]} 0 10
[junit4:junit4] 2> 628577 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438814244089888768)]} 0 1
[junit4:junit4] 2> 628586 T1798 C367 P34399 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438814244096180224)]} 0 1
[junit4:junit4] 2> 628586 T1834 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438814244096180224)]} 0 1
[junit4:junit4] 2> 628586 T1815 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438814244096180224)]} 0 1
[junit4:junit4] 2> 628587 T1788 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34410/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1438814244096180224)]} 0 5
[junit4:junit4] 2> 628588 T1836 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 9
[junit4:junit4] 2> 628592 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438814244105617408)]} 0 1
[junit4:junit4] 2> 628595 T1784 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:34399/collection1/]
[junit4:junit4] 2> 628596 T1784 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34399/collection1/ against:[http://127.0.0.1:34399/collection1/] result:true
[junit4:junit4] 2> 628596 T1784 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34403/collection1/ against:[http://127.0.0.1:34399/collection1/] result:false
[junit4:junit4] 2> 628596 T1784 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34410/collection1/ against:[http://127.0.0.1:34399/collection1/] result:false
[junit4:junit4] 2> 628601 T1815 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&wt=javabin&version=2} {add=[2 (1438814244111908864)]} 0 1
[junit4:junit4] 2> 628601 T1834 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&wt=javabin&version=2} {add=[2 (1438814244111908864)]} 0 1
[junit4:junit4] 2> 628602 T1784 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&wt=javabin&version=2} {add=[2 (1438814244111908864)]} 0 7
[junit4:junit4] 2> 628606 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438814244120297472)]} 0 1
[junit4:junit4] 2> 628612 T1788 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:34399/collection1/]
[junit4:junit4] 2> 628613 T1788 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34399/collection1/ against:[http://127.0.0.1:34399/collection1/] result:true
[junit4:junit4] 2> 628613 T1788 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34403/collection1/ against:[http://127.0.0.1:34399/collection1/] result:false
[junit4:junit4] 2> 628614 T1788 C365 P34395 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34410/collection1/ against:[http://127.0.0.1:34399/collection1/] result:false
[junit4:junit4] 2> 628618 T1834 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&wt=javabin&version=2} {add=[3 (1438814244129734656)]} 0 1
[junit4:junit4] 2> 628618 T1815 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34395/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&wt=javabin&version=2} {add=[3 (1438814244129734656)]} 0 1
[junit4:junit4] 2> 628619 T1788 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34410/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&wt=javabin&version=2} {add=[3 (1438814244129734656)]} 0 7
[junit4:junit4] 2> 628620 T1836 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:34399/collection1/&test.distrib.skip.servers=http://127.0.0.1:34403/collection1/&wt=javabin&version=2} {add=[3]} 0 11
[junit4:junit4] 2> 628622 T1762 C366 P34391 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 628666 T1762 C366 P34391 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 628667 T1762 C366 P34391 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 628671 T1762 C366 P34391 oass.SolrIndexSearcher.<init> Opening Searcher@7cb7e49f main
[junit4:junit4] 2> 628672 T1762 C366 P34391 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 628673 T1776 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7cb7e49f main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 628674 T1762 C366 P34391 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 52
[junit4:junit4] 2> 628676 T1817 C368 P34403 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:34395/collection1/, StdNode: http://127.0.0.1:34399/collection1/, StdNode: http://127.0.0.1:34403/collection1/, StdNode: http://127.0.0.1:34410/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 628679 T1782 C365 P34395 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 628680 T1818 C368 P34403 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 628680 T1837 C364 P34410 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 628680 T1800 C367 P34399 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 628727 T1782 C365 P34395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff732d9; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 628728 T1782 C365 P34395 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 628731 T1782 C365 P34395 oass.SolrIndexSearcher.<init> Opening Searcher@71bc71f7 main
[junit4:junit4] 2> 628732 T1782 C365 P34395 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 628733 T1794 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71bc71f7 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 628733 T1782 C365 P34395 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 54
[junit4:junit4] 2> 628746 T1837 C364 P34410 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a2eecb7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 628747 T1837 C364 P34410 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 628751 T1837 C364 P34410 oass.SolrIndexSearcher.<init> Opening Searcher@3c0f8972 main
[junit4:junit4] 2> 628751 T1837 C364 P34410 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 628752 T1848 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3c0f8972 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 628753 T1837 C364 P34410 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 73
[junit4:junit4] 2> 628754 T1818 C368 P34403 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@538b32a1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 628754 T1800 C367 P34399 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@14a3213b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 628755 T1818 C368 P34403 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 628755 T1800 C367 P34399 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 628760 T1818 C368 P34403 oass.SolrIndexSearcher.<init> Opening Searcher@51f5def6 main
[junit4:junit4] 2> 628760 T1800 C367 P34399 oass.SolrIndexSearcher.<init> Opening Searcher@aff49f1 main
[junit4:junit4] 2> 628761 T1818 C368 P34403 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 628761 T1829 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51f5def6 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 628761 T1800 C367 P34399 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 628762 T1818 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 82
[junit4:junit4] 2> 628762 T1810 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@aff49f1 main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 628763 T1800 C367 P34399 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 83
[junit4:junit4] 2> 628764 T1817 C368 P34403 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 87
[junit4:junit4] 2> 628764 T1750 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 628765 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 628766 T1750 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 628769 T1787 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 628772 T1799 C367 P34399 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 628775 T1816 C368 P34403 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 628778 T1835 C364 P34410 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 628779 T1750 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 628798 T1819 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 628799 T1819 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 628812 T1862 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 628813 T1862 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34395/collection1/
[junit4:junit4] 2> 628813 T1862 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34395 START replicas=[http://127.0.0.1:34399/collection1/, http://127.0.0.1:34403/collection1/, http://127.0.0.1:34410/collection1/] nUpdates=100
[junit4:junit4] 2> 628815 T1801 C367 P34399 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628815 T1820 C368 P34403 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628816 T1862 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34395 Received 3 versions from 127.0.0.1:34399/collection1/
[junit4:junit4] 2> 628815 T1838 C364 P34410 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628816 T1862 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34395 Our versions are newer. ourLowThreshold=1438814244059480064 otherHigh=1438814244096180224
[junit4:junit4] 2> 628817 T1862 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34395 Received 5 versions from 127.0.0.1:34403/collection1/
[junit4:junit4] 2> 628817 T1862 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34395 Our versions are newer. ourLowThreshold=1438814244059480064 otherHigh=1438814244111908864
[junit4:junit4] 2> 628818 T1862 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34395 Received 5 versions from 127.0.0.1:34410/collection1/
[junit4:junit4] 2> 628818 T1862 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34395 Our versions are newer. ourLowThreshold=1438814244059480064 otherHigh=1438814244111908864
[junit4:junit4] 2> 628819 T1862 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34395 DONE. sync succeeded
[junit4:junit4] 2> 628819 T1862 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 628819 T1862 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/: try and ask http://127.0.0.1:34399/collection1/ to sync
[junit4:junit4] 2> 628820 T1862 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/: try and ask http://127.0.0.1:34403/collection1/ to sync
[junit4:junit4] 2> 628820 T1862 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/: try and ask http://127.0.0.1:34410/collection1/ to sync
[junit4:junit4] 2> 628821 T1802 C367 P34399 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34399 START replicas=[http://127.0.0.1:34395/collection1/] nUpdates=100
[junit4:junit4] 2> 628821 T1821 C368 P34403 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34403 START replicas=[http://127.0.0.1:34395/collection1/] nUpdates=100
[junit4:junit4] 2> 628822 T1839 C364 P34410 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34410 START replicas=[http://127.0.0.1:34395/collection1/] nUpdates=100
[junit4:junit4] 2> 628823 T1872 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628824 T1873 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628824 T1783 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628824 T1821 C368 P34403 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34403 Received 5 versions from 127.0.0.1:34395/collection1/
[junit4:junit4] 2> 628825 T1802 C367 P34399 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34399 Received 5 versions from 127.0.0.1:34395/collection1/
[junit4:junit4] 2> 628825 T1839 C364 P34410 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34410 Received 5 versions from 127.0.0.1:34395/collection1/
[junit4:junit4] 2> 628826 T1802 C367 P34399 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:34399 Requesting updates from 127.0.0.1:34395/collection1/n=2 versions=[1438814244129734656, 1438814244111908864]
[junit4:junit4] 2> 628825 T1821 C368 P34403 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34403 Our versions are newer. ourLowThreshold=1438814244059480064 otherHigh=1438814244111908864
[junit4:junit4] 2> 628826 T1839 C364 P34410 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34410 Our versions are newer. ourLowThreshold=1438814244059480064 otherHigh=1438814244111908864
[junit4:junit4] 2> 628827 T1821 C368 P34403 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34403 DONE. sync succeeded
[junit4:junit4] 2> 628827 T1839 C364 P34410 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34410 DONE. sync succeeded
[junit4:junit4] 2> 628828 T1821 C368 P34403 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:34395/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=7
[junit4:junit4] 2> 628828 T1839 C364 P34410 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:34395/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=6
[junit4:junit4] 2> 628829 T1862 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/: sync completed with http://127.0.0.1:34403/collection1/
[junit4:junit4] 2> 628829 T1862 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/: sync completed with http://127.0.0.1:34410/collection1/
[junit4:junit4] 2> 628829 T1783 C365 P34395 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1438814244129734656,1438814244111908864&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 628836 T1802 C367 P34399 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438814244111908864), 3 (1438814244129734656)]} 0 6
[junit4:junit4] 2> 628836 T1802 C367 P34399 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34399 DONE. sync succeeded
[junit4:junit4] 2> 628837 T1802 C367 P34399 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:34395/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=16
[junit4:junit4] 2> 628837 T1862 oasc.SyncStrategy.syncToMe http://127.0.0.1:34395/collection1/: sync completed with http://127.0.0.1:34399/collection1/
[junit4:junit4] 2> 628838 T1862 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={shard=shard1&action=REQUESTSYNCSHARD&core=collection1&collection=collection1&wt=javabin&version=2} status=0 QTime=26
[junit4:junit4] 2> 628838 T1819 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=40
[junit4:junit4] 2> 628839 T1750 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 628840 T1750 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 628841 T1750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 628842 T1750 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 628844 T1762 C366 P34391 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 628850 T1762 C366 P34391 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372160162360/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@679bf6dd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 628851 T1762 C366 P34391 oasc.SolrDeletionPolicy.updat
[...truncated too long message...]
"state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34403_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34403",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34410_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34410"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"1":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "node_name":"127.0.0.1:34391_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34391",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/live_nodes (4)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:34410_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:34395_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:34391_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:34403_ (0)
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/collections (2)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925888400949262-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925888400949258-4-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925888400949260-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34403_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34403"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89925888400949251-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34391_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34391"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89925888400949251-127.0.0.1:34391_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925888400949258-127.0.0.1:34403_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925888400949262-127.0.0.1:34395_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925888400949260-127.0.0.1:34410_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89925888400949251-127.0.0.1:34391_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=1EF5BDA2D1848B85 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=da -Dtests.timezone=Asia/Kolkata -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 467s J1 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:34395/collection1lastClient and got 248 from http://127.0.0.1:34403/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([1EF5BDA2D1848B85:9F1333BAA6DBEBB9]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1066934 T1750 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 466678 T1749 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> 1067862 T1844 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1067862 T1844 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> 1067862 T1844 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=DefaultSimilarity, locale=da, timezone=Asia/Kolkata
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=235539416,total=439353344
[junit4:junit4] 2> NOTE: All tests run in this JVM: [JsonLoaderTest, ShardRoutingCustomTest, TermVectorComponentTest, TestSchemaSimilarityResource, SimplePostToolTest, TestSolrXmlPersistence, JSONWriterTest, TimeZoneUtilsTest, TestBM25SimilarityFactory, PreAnalyzedUpdateProcessorTest, CurrencyFieldOpenExchangeTest, TestCodecSupport, ClusterStateUpdateTest, TestSerializedLuceneMatchVersion, TermVectorComponentDistributedTest, AliasIntegrationTest, TestAddFieldRealTimeGet, TestIndexSearcher, TestComponentsName, QueryResultKeyTest, RegexBoostProcessorTest, TestCSVLoader, SuggesterTSTTest, LoggingHandlerTest, TestDynamicFieldCollectionResource, IndexReaderFactoryTest, SpatialFilterTest, TestClassNameShortening, TestZkChroot, TestWriterPerf, SolrIndexConfigTest, FullSolrCloudDistribCmdsTest, TestCloudManagedSchemaAddField, HardAutoCommitTest, UpdateRequestProcessorFactoryTest, BasicDistributedZkTest, TestLMJelinekMercerSimilarityFactory, DirectSolrSpellCheckerTest, QueryElevationComponentTest, TestFieldTypeResource, TestShardHandlerFactory, SOLR749Test, TestDistributedGrouping, EchoParamsTest, TestQueryUtils, ReturnFieldsTest, TestFastLRUCache, TestLFUCache, TestPerFieldSimilarity, BadCopyFieldTest, TestElisionMultitermQuery, TestAtomicUpdateErrorCases, TestReversedWildcardFilterFactory, SyncSliceTest]
[junit4:junit4] Completed on J1 in 467.72s, 1 test, 1 failure <<< FAILURES!
[...truncated 537 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:392: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:372: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 55 minutes 13 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure