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/24 14:48:04 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1734 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1734/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:26155/w/b/collection1lastClient and got 248 from http://127.0.0.1:18622/w/b/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:26155/w/b/collection1lastClient and got 248 from http://127.0.0.1:18622/w/b/collection1
at __randomizedtesting.SeedInfo.seed([C088980BD06DB6BB:416E1613A732D687]: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:616)
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:679)
Build Log:
[...truncated 8927 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 272562 T709 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /w/b
[junit4:junit4] 2> 272568 T709 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372075970788
[junit4:junit4] 2> 272569 T709 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 272570 T710 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 272671 T709 oasc.ZkTestServer.run start zk server on port:38866
[junit4:junit4] 2> 272672 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 272676 T716 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12ecb5db name:ZooKeeperConnection Watcher:127.0.0.1:38866 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 272677 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 272677 T709 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 272683 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 272692 T718 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f9dfa2f name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 272692 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 272692 T709 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 272703 T709 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 272706 T709 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 272708 T709 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 272717 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 272718 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 272732 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 272733 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 272737 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 272738 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 272742 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 272743 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 272746 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 272747 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 272755 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 272756 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 272760 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 272760 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 272764 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 272765 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 272768 T709 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 272769 T709 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 273030 T709 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 273036 T709 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43020
[junit4:junit4] 2> 273037 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 273038 T709 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 273038 T709 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992
[junit4:junit4] 2> 273039 T709 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/solr.xml
[junit4:junit4] 2> 273039 T709 oasc.CoreContainer.<init> New CoreContainer 1693101992
[junit4:junit4] 2> 273040 T709 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/'
[junit4:junit4] 2> 273041 T709 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/'
[junit4:junit4] 2> 273149 T709 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 273150 T709 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 273151 T709 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 273151 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 273152 T709 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 273152 T709 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 273153 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 273153 T709 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 273154 T709 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 273154 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 273171 T709 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 273172 T709 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38866/solr
[junit4:junit4] 2> 273172 T709 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 273173 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 273176 T729 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1071a9f3 name:ZooKeeperConnection Watcher:127.0.0.1:38866 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 273177 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 273186 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 273198 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 273200 T731 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@650d1c98 name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 273200 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 273203 T709 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 273214 T709 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 273218 T709 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 273221 T709 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43020_w%2Fb
[junit4:junit4] 2> 273228 T709 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43020_w%2Fb
[junit4:junit4] 2> 273231 T709 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 273244 T709 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 273253 T709 oasc.Overseer.start Overseer (id=89920370822021123-127.0.0.1:43020_w%2Fb-n_0000000000) starting
[junit4:junit4] 2> 273258 T709 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 273269 T733 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 273270 T709 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 273273 T709 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 273279 T709 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 273282 T732 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 273286 T734 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 273286 T734 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 274787 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 274788 T732 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:43020_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43020/w/b"}
[junit4:junit4] 2> 274788 T732 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 274788 T732 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 274832 T731 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> 275290 T734 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/collection1
[junit4:junit4] 2> 275290 T734 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 275291 T734 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 275292 T734 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 275293 T734 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/collection1/'
[junit4:junit4] 2> 275295 T734 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 275296 T734 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/collection1/lib/README' to classloader
[junit4:junit4] 2> 275350 T734 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 275410 T734 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 275412 T734 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 275419 T734 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 276037 T734 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 276037 T734 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 276038 T734 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 276051 T734 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 276055 T734 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 276072 T734 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 276077 T734 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 276081 T734 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 276082 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 276083 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 276083 T734 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 276084 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 276085 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 276085 T734 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 276133 T734 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372075970992/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/
[junit4:junit4] 2> 276133 T734 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7fb6634c
[junit4:junit4] 2> 276134 T734 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 276136 T734 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data
[junit4:junit4] 2> 276137 T734 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index/
[junit4:junit4] 2> 276138 T734 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 276139 T734 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index
[junit4:junit4] 2> 276149 T734 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 276150 T734 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 276153 T734 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 276153 T734 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 276154 T734 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 276155 T734 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 276156 T734 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 276156 T734 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 276156 T734 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 276157 T734 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 276158 T734 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 276167 T734 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 276177 T734 oass.SolrIndexSearcher.<init> Opening Searcher@c62d2ab main
[junit4:junit4] 2> 276178 T734 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 276179 T734 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 276183 T735 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c62d2ab main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 276185 T734 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 276186 T734 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43020/w/b collection:control_collection shard:shard1
[junit4:junit4] 2> 276186 T734 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 276202 T734 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 276214 T734 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 276214 T734 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 276214 T734 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43020/w/b/collection1/
[junit4:junit4] 2> 276215 T734 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 276215 T734 oasc.SyncStrategy.syncToMe http://127.0.0.1:43020/w/b/collection1/ has no replicas
[junit4:junit4] 2> 276216 T734 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43020/w/b/collection1/
[junit4:junit4] 2> 276216 T734 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 276336 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 276354 T731 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> 276389 T734 oasc.ZkController.register We are http://127.0.0.1:43020/w/b/collection1/ and leader is http://127.0.0.1:43020/w/b/collection1/
[junit4:junit4] 2> 276389 T734 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43020/w/b
[junit4:junit4] 2> 276389 T734 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 276390 T734 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 276390 T734 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 276392 T734 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 276393 T709 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 276394 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 276395 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 276413 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 276415 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 276418 T738 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5545757a name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 276418 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 276420 T709 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 276422 T709 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 276689 T709 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 276692 T709 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:26155
[junit4:junit4] 2> 276693 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 276693 T709 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 276694 T709 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642
[junit4:junit4] 2> 276694 T709 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/solr.xml
[junit4:junit4] 2> 276695 T709 oasc.CoreContainer.<init> New CoreContainer 507274563
[junit4:junit4] 2> 276696 T709 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/'
[junit4:junit4] 2> 276696 T709 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/'
[junit4:junit4] 2> 276813 T709 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 276814 T709 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 276814 T709 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 276815 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 276815 T709 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 276816 T709 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 276816 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 276817 T709 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 276818 T709 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 276818 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 276837 T709 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 276838 T709 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38866/solr
[junit4:junit4] 2> 276838 T709 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 276839 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 276846 T749 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@41fbfa37 name:ZooKeeperConnection Watcher:127.0.0.1:38866 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 276846 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 276905 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 276916 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 276919 T751 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@303459ed name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 276919 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 276995 T709 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 277867 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 277868 T732 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:43020_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43020/w/b"}
[junit4:junit4] 2> 277879 T731 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> 277879 T738 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> 277879 T751 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> 277998 T709 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26155_w%2Fb
[junit4:junit4] 2> 278003 T709 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:26155_w%2Fb
[junit4:junit4] 2> 278006 T731 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> 278006 T751 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> 278006 T738 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 278007 T738 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> 278007 T731 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 278013 T751 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 278018 T752 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 278019 T752 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 279396 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 279397 T732 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:26155_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26155/w/b"}
[junit4:junit4] 2> 279398 T732 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 279398 T732 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 279451 T731 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> 279451 T738 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> 279451 T751 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> 280022 T752 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/collection1
[junit4:junit4] 2> 280022 T752 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 280023 T752 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 280024 T752 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 280025 T752 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/collection1/'
[junit4:junit4] 2> 280027 T752 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 280027 T752 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/collection1/lib/README' to classloader
[junit4:junit4] 2> 280078 T752 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 280135 T752 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 280137 T752 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 280143 T752 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 280693 T752 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 280694 T752 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 280695 T752 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 280703 T752 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 280706 T752 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 280717 T752 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 280721 T752 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 280724 T752 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 280725 T752 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 280725 T752 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 280726 T752 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 280726 T752 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 280726 T752 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 280727 T752 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 280727 T752 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372075974642/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/
[junit4:junit4] 2> 280727 T752 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7fb6634c
[junit4:junit4] 2> 280728 T752 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 280729 T752 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1
[junit4:junit4] 2> 280729 T752 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index/
[junit4:junit4] 2> 280730 T752 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 280730 T752 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index
[junit4:junit4] 2> 280736 T752 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 280736 T752 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 280739 T752 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 280739 T752 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 280739 T752 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 280740 T752 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 280741 T752 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 280741 T752 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 280741 T752 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 280742 T752 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 280742 T752 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 280748 T752 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 280755 T752 oass.SolrIndexSearcher.<init> Opening Searcher@1966d19d main
[junit4:junit4] 2> 280756 T752 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 280756 T752 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 280760 T753 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1966d19d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 280761 T752 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 280762 T752 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:26155/w/b collection:collection1 shard:shard1
[junit4:junit4] 2> 280762 T752 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 280777 T752 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 280788 T752 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 280789 T752 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 280789 T752 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 280789 T752 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 280789 T752 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/ has no replicas
[junit4:junit4] 2> 280790 T752 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 280790 T752 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 280955 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 280972 T731 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> 280972 T751 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> 280972 T738 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> 280999 T752 oasc.ZkController.register We are http://127.0.0.1:26155/w/b/collection1/ and leader is http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 280999 T752 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26155/w/b
[junit4:junit4] 2> 281000 T752 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 281000 T752 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 281000 T752 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 281003 T752 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 281004 T709 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 281005 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 281005 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 281201 T709 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 281204 T709 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18616
[junit4:junit4] 2> 281205 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 281205 T709 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 281205 T709 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236
[junit4:junit4] 2> 281206 T709 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/solr.xml
[junit4:junit4] 2> 281206 T709 oasc.CoreContainer.<init> New CoreContainer 1362767943
[junit4:junit4] 2> 281207 T709 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/'
[junit4:junit4] 2> 281207 T709 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/'
[junit4:junit4] 2> 281279 T709 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 281280 T709 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 281280 T709 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 281280 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 281281 T709 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 281281 T709 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 281282 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 281282 T709 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 281282 T709 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 281283 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 281294 T709 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 281295 T709 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38866/solr
[junit4:junit4] 2> 281295 T709 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 281296 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 281299 T765 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7cc0c18f name:ZooKeeperConnection Watcher:127.0.0.1:38866 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 281300 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 281311 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 281325 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 281327 T767 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7064543b name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 281327 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 281339 T709 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 282342 T709 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18616_w%2Fb
[junit4:junit4] 2> 282347 T709 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18616_w%2Fb
[junit4:junit4] 2> 282349 T731 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> 282349 T751 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> 282351 T767 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 282351 T738 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 282351 T738 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> 282352 T731 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 282353 T751 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 282358 T768 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 282358 T768 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 282486 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 282487 T732 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:26155_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26155/w/b"}
[junit4:junit4] 2> 282491 T732 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:18616_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18616/w/b"}
[junit4:junit4] 2> 282491 T732 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 282492 T732 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 282511 T731 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> 282511 T767 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> 282511 T738 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> 282511 T751 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> 283368 T768 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/collection1
[junit4:junit4] 2> 283368 T768 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 283369 T768 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 283369 T768 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 283371 T768 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/collection1/'
[junit4:junit4] 2> 283372 T768 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 283373 T768 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/collection1/lib/README' to classloader
[junit4:junit4] 2> 283423 T768 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 283480 T768 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 283482 T768 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 283488 T768 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 284083 T768 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 284085 T768 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 284085 T768 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 284093 T768 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 284096 T768 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 284109 T768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 284113 T768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 284116 T768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 284117 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 284117 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 284117 T768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 284118 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 284118 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 284119 T768 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 284119 T768 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372075979236/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/
[junit4:junit4] 2> 284119 T768 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7fb6634c
[junit4:junit4] 2> 284120 T768 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 284121 T768 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2
[junit4:junit4] 2> 284121 T768 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index/
[junit4:junit4] 2> 284122 T768 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 284122 T768 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index
[junit4:junit4] 2> 284127 T768 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 284128 T768 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 284130 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 284130 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 284131 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 284131 T768 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 284132 T768 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 284132 T768 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 284133 T768 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 284133 T768 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 284133 T768 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 284140 T768 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 284146 T768 oass.SolrIndexSearcher.<init> Opening Searcher@55c923e4 main
[junit4:junit4] 2> 284147 T768 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 284147 T768 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 284151 T769 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55c923e4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 284153 T768 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 284153 T768 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18616/w/b collection:collection1 shard:shard1
[junit4:junit4] 2> 284157 T768 oasc.ZkController.register We are http://127.0.0.1:18616/w/b/collection1/ and leader is http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 284157 T768 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18616/w/b
[junit4:junit4] 2> 284157 T768 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 284157 T768 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C115 name=collection1 org.apache.solr.core.SolrCore@43095f4 url=http://127.0.0.1:18616/w/b/collection1 node=127.0.0.1:18616_w%2Fb C115_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:18616_w%2Fb, base_url=http://127.0.0.1:18616/w/b}
[junit4:junit4] 2> 284157 T770 C115 P18616 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 284158 T770 C115 P18616 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 284158 T768 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 284158 T770 C115 P18616 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 284159 T770 C115 P18616 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 284159 T709 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 284160 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 284160 T770 C115 P18616 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 284160 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 284175 T741 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 284345 T709 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 284347 T709 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18622
[junit4:junit4] 2> 284348 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 284348 T709 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 284349 T709 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393
[junit4:junit4] 2> 284349 T709 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/solr.xml
[junit4:junit4] 2> 284349 T709 oasc.CoreContainer.<init> New CoreContainer 449262134
[junit4:junit4] 2> 284350 T709 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/'
[junit4:junit4] 2> 284350 T709 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/'
[junit4:junit4] 2> 284426 T709 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 284426 T709 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 284427 T709 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 284427 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 284428 T709 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 284428 T709 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 284428 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 284429 T709 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 284429 T709 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 284429 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 284441 T709 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 284442 T709 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38866/solr
[junit4:junit4] 2> 284442 T709 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 284443 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 284446 T782 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@39170465 name:ZooKeeperConnection Watcher:127.0.0.1:38866 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 284446 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 284459 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 284472 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 284474 T784 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@223f6902 name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 284474 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 284479 T709 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 285482 T709 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18622_w%2Fb
[junit4:junit4] 2> 285484 T709 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18622_w%2Fb
[junit4:junit4] 2> 285487 T731 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> 285488 T767 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> 285488 T784 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285488 T751 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> 285488 T738 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285489 T738 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> 285489 T731 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285499 T767 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285499 T751 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285505 T785 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 285505 T785 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 285526 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 285527 T732 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:18616_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18616/w/b"}
[junit4:junit4] 2> 285531 T732 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:18622_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18622/w/b"}
[junit4:junit4] 2> 285531 T732 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 285531 T732 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 285542 T731 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> 285543 T767 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> 285543 T738 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> 285543 T751 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> 285543 T784 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> 286178 T741 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 286178 T741 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:18616_w%252Fb&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 286508 T785 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/collection1
[junit4:junit4] 2> 286508 T785 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 286509 T785 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 286509 T785 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 286511 T785 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/collection1/'
[junit4:junit4] 2> 286512 T785 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/collection1/lib/README' to classloader
[junit4:junit4] 2> 286513 T785 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 286564 T785 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 286621 T785 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 286623 T785 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 286629 T785 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 287256 T785 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 287257 T785 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 287258 T785 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 287270 T785 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 287275 T785 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 287291 T785 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 287295 T785 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 287300 T785 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 287301 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 287302 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 287302 T785 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 287303 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 287303 T785 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 287304 T785 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 287304 T785 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372075982393/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/
[junit4:junit4] 2> 287305 T785 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7fb6634c
[junit4:junit4] 2> 287305 T785 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 287306 T785 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3
[junit4:junit4] 2> 287307 T785 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index/
[junit4:junit4] 2> 287308 T785 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 287309 T785 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index
[junit4:junit4] 2> 287321 T785 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 287322 T785 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 287325 T785 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 287326 T785 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 287326 T785 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 287327 T785 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 287328 T785 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 287328 T785 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 287329 T785 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 287330 T785 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 287330 T785 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 287340 T785 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 287349 T785 oass.SolrIndexSearcher.<init> Opening Searcher@103219d3 main
[junit4:junit4] 2> 287351 T785 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 287351 T785 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 287357 T786 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@103219d3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 287359 T785 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 287360 T785 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18622/w/b collection:collection1 shard:shard1
[junit4:junit4] 2> 287364 T785 oasc.ZkController.register We are http://127.0.0.1:18622/w/b/collection1/ and leader is http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 287364 T785 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18622/w/b
[junit4:junit4] 2> 287364 T785 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 287364 T785 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C116 name=collection1 org.apache.solr.core.SolrCore@68e881a4 url=http://127.0.0.1:18622/w/b/collection1 node=127.0.0.1:18622_w%2Fb C116_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:18622_w%2Fb, base_url=http://127.0.0.1:18622/w/b}
[junit4:junit4] 2> 287365 T787 C116 P18622 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 287366 T785 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 287366 T787 C116 P18622 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 287366 T787 C116 P18622 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 287367 T787 C116 P18622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 287367 T709 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 287368 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 287368 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 287376 T787 C116 P18622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 287391 T742 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 287645 T709 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 287649 T709 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18627
[junit4:junit4] 2> 287650 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 287650 T709 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 287651 T709 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607
[junit4:junit4] 2> 287651 T709 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/solr.xml
[junit4:junit4] 2> 287652 T709 oasc.CoreContainer.<init> New CoreContainer 74477307
[junit4:junit4] 2> 287652 T709 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/'
[junit4:junit4] 2> 287653 T709 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/'
[junit4:junit4] 2> 287762 T709 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 287763 T709 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 287763 T709 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 287764 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 287764 T709 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 287765 T709 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 287765 T709 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 287766 T709 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 287766 T709 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 287767 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 287785 T709 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 287786 T709 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38866/solr
[junit4:junit4] 2> 287786 T709 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 287787 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 287790 T799 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d64d42f name:ZooKeeperConnection Watcher:127.0.0.1:38866 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 287791 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 287807 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 287820 T709 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 287822 T801 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@583dfc8b name:ZooKeeperConnection Watcher:127.0.0.1:38866/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 287822 T709 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 287835 T709 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C117 name=collection1 org.apache.solr.core.SolrCore@43095f4 url=http://127.0.0.1:18616/w/b/collection1 node=127.0.0.1:18616_w%2Fb C117_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18616_w%2Fb, base_url=http://127.0.0.1:18616/w/b}
[junit4:junit4] 2> 288180 T770 C117 P18616 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:26155/w/b/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 288180 T770 C117 P18616 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18616/w/b START replicas=[http://127.0.0.1:26155/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 288181 T770 C117 P18616 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 288182 T770 C117 P18616 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 288182 T770 C117 P18616 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 288182 T770 C117 P18616 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 288182 T770 C117 P18616 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 288183 T770 C117 P18616 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:26155/w/b/collection1/. core=collection1
[junit4:junit4] 2> 288183 T770 C117 P18616 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C118 name=collection1 org.apache.solr.core.SolrCore@19b3a8db url=http://127.0.0.1:26155/w/b/collection1 node=127.0.0.1:26155_w%2Fb C118_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26155_w%2Fb, base_url=http://127.0.0.1:26155/w/b, leader=true}
[junit4:junit4] 2> 288190 T743 C118 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 288197 T744 C118 P26155 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 288202 T744 C118 P26155 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 288203 T744 C118 P26155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 288207 T744 C118 P26155 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 288208 T744 C118 P26155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 288210 T744 C118 P26155 oass.SolrIndexSearcher.<init> Opening Searcher@66b309a1 realtime
[junit4:junit4] 2> 288210 T744 C118 P26155 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 288211 T744 C118 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 288212 T770 C117 P18616 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 288212 T770 C117 P18616 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 288215 T745 C118 P26155 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 288215 T745 C118 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 288216 T770 C117 P18616 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 288216 T770 C117 P18616 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 288217 T770 C117 P18616 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 288220 T745 C118 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 288221 T770 C117 P18616 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 288222 T770 C117 P18616 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index.20130624024306440
[junit4:junit4] 2> 288223 T770 C117 P18616 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index.20130624024306440 lockFactory=org.apache.lucene.store.NativeFSLockFactory@143dfa7c; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 288227 T745 C118 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C119 name=collection1 org.apache.solr.core.SolrCore@43095f4 url=http://127.0.0.1:18616/w/b/collection1 node=127.0.0.1:18616_w%2Fb C119_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18616_w%2Fb, base_url=http://127.0.0.1:18616/w/b}
[junit4:junit4] 2> 288233 T770 C119 P18616 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 288236 T770 C119 P18616 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 288236 T770 C119 P18616 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 288242 T770 C119 P18616 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 288242 T770 C119 P18616 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 288243 T770 C119 P18616 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 288244 T770 C119 P18616 oass.SolrIndexSearcher.<init> Opening Searcher@694c68ff main
[junit4:junit4] 2> 288245 T769 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@694c68ff main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 288246 T770 C119 P18616 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index.20130624024306440 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index.20130624024306440;done=true>>]
[junit4:junit4] 2> 288246 T770 C119 P18616 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index.20130624024306440
[junit4:junit4] 2> 288247 T770 C119 P18616 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index.20130624024306440
[junit4:junit4] 2> 288256 T770 C119 P18616 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 288256 T770 C119 P18616 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 288256 T770 C119 P18616 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 288257 T770 C119 P18616 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 288258 T770 C119 P18616 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 288558 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 288559 T732 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:18622_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18622/w/b"}
[junit4:junit4] 2> 288563 T732 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:18616_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18616/w/b"}
[junit4:junit4] 2> 288576 T731 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> 288576 T767 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> 288576 T751 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> 288576 T738 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> 288576 T801 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> 288576 T784 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> 288839 T709 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18627_w%2Fb
[junit4:junit4] 2> 288841 T709 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18627_w%2Fb
[junit4:junit4] 2> 288843 T731 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> 288843 T751 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> 288843 T767 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> 288843 T801 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> 288844 T738 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 288843 T784 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 288845 T731 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 288845 T738 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> 288845 T784 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> 288853 T751 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 288853 T767 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 288854 T801 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 288863 T804 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 288863 T804 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 289394 T742 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 289394 T742 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:18622_w%252Fb&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 290090 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 290091 T732 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:18627_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18627/w/b"}
[junit4:junit4] 2> 290091 T732 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 290091 T732 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 290096 T731 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> 290096 T767 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> 290096 T801 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> 290096 T738 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> 290096 T751 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> 290096 T784 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> 290867 T804 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/collection1
[junit4:junit4] 2> 290867 T804 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 290868 T804 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 290868 T804 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 290870 T804 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/collection1/'
[junit4:junit4] 2> 290871 T804 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 290872 T804 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/collection1/lib/README' to classloader
[junit4:junit4] 2> 290949 T804 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 291006 T804 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 291008 T804 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 291014 T804 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C120 name=collection1 org.apache.solr.core.SolrCore@68e881a4 url=http://127.0.0.1:18622/w/b/collection1 node=127.0.0.1:18622_w%2Fb C120_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18622_w%2Fb, base_url=http://127.0.0.1:18622/w/b}
[junit4:junit4] 2> 291396 T787 C120 P18622 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:26155/w/b/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 291396 T787 C120 P18622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18622/w/b START replicas=[http://127.0.0.1:26155/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 291398 T787 C120 P18622 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 291398 T787 C120 P18622 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 291399 T787 C120 P18622 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 291399 T787 C120 P18622 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 291399 T787 C120 P18622 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 291399 T787 C120 P18622 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:26155/w/b/collection1/. core=collection1
[junit4:junit4] 2> 291400 T787 C120 P18622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C121 name=collection1 org.apache.solr.core.SolrCore@19b3a8db url=http://127.0.0.1:26155/w/b/collection1 node=127.0.0.1:26155_w%2Fb C121_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26155_w%2Fb, base_url=http://127.0.0.1:26155/w/b, leader=true}
[junit4:junit4] 2> 291401 T743 C121 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 291421 T746 C121 P26155 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 291439 T746 C121 P26155 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 291440 T746 C121 P26155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 291442 T746 C121 P26155 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 291442 T746 C121 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 291443 T787 C120 P18622 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 291444 T787 C120 P18622 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 291446 T745 C121 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 291447 T787 C120 P18622 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 291448 T787 C120 P18622 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 291448 T787 C120 P18622 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 291451 T745 C121 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 291452 T787 C120 P18622 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 291454 T787 C120 P18622 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index.20130624024309671
[junit4:junit4] 2> 291455 T787 C120 P18622 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index.20130624024309671 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c3bb813; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> ASYNC NEW_CORE C122 name=collection1 org.apache.solr.core.SolrCore@19b3a8db url=http://127.0.0.1:26155/w/b/collection1 node=127.0.0.1:26155_w%2Fb C122_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26155_w%2Fb, base_url=http://127.0.0.1:26155/w/b, leader=true}
[junit4:junit4] 2> 291463 T745 C122 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C123 name=collection1 org.apache.solr.core.SolrCore@68e881a4 url=http://127.0.0.1:18622/w/b/collection1 node=127.0.0.1:18622_w%2Fb C123_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18622_w%2Fb, base_url=http://127.0.0.1:18622/w/b}
[junit4:junit4] 2> 291465 T787 C123 P18622 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 291469 T787 C123 P18622 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 291469 T787 C123 P18622 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 291475 T787 C123 P18622 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 291476 T787 C123 P18622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 291476 T787 C123 P18622 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 291477 T787 C123 P18622 oass.SolrIndexSearcher.<init> Opening Searcher@5b5b0e9f main
[junit4:junit4] 2> 291479 T786 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5b5b0e9f main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 291480 T787 C123 P18622 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index.20130624024309671 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index.20130624024309671;done=true>>]
[junit4:junit4] 2> 291480 T787 C123 P18622 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index.20130624024309671
[junit4:junit4] 2> 291480 T787 C123 P18622 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index.20130624024309671
[junit4:junit4] 2> 291481 T787 C123 P18622 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 291482 T787 C123 P18622 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 291482 T787 C123 P18622 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 291482 T787 C123 P18622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 291484 T787 C123 P18622 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 291601 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 291602 T732 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:18622_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18622/w/b"}
[junit4:junit4] 2> 291615 T731 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> 291615 T751 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> 291615 T767 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> 291615 T801 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> 291615 T738 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> 291615 T784 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> 291648 T804 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 291649 T804 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 291650 T804 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 291662 T804 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 291666 T804 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 291682 T804 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 291694 T804 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 291699 T804 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 291700 T804 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 291700 T804 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 291701 T804 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 291702 T804 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 291702 T804 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 291703 T804 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 291703 T804 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372075985607/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/
[junit4:junit4] 2> 291703 T804 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7fb6634c
[junit4:junit4] 2> 291704 T804 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 291705 T804 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4
[junit4:junit4] 2> 291706 T804 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index/
[junit4:junit4] 2> 291707 T804 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 291708 T804 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index
[junit4:junit4] 2> 291715 T804 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 291715 T804 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 291719 T804 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 291719 T804 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 291720 T804 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 291721 T804 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 291722 T804 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 291722 T804 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 291725 T804 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 291726 T804 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 291727 T804 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 291736 T804 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 291746 T804 oass.SolrIndexSearcher.<init> Opening Searcher@5bde2a20 main
[junit4:junit4] 2> 291747 T804 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 291747 T804 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 291753 T807 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5bde2a20 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 291756 T804 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 291756 T804 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18627/w/b collection:collection1 shard:shard1
[junit4:junit4] 2> 291763 T804 oasc.ZkController.register We are http://127.0.0.1:18627/w/b/collection1/ and leader is http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 291764 T804 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18627/w/b
[junit4:junit4] 2> 291764 T804 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 291765 T804 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C124 name=collection1 org.apache.solr.core.SolrCore@47f15427 url=http://127.0.0.1:18627/w/b/collection1 node=127.0.0.1:18627_w%2Fb C124_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:18627_w%2Fb, base_url=http://127.0.0.1:18627/w/b}
[junit4:junit4] 2> 291765 T808 C124 P18627 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 291766 T804 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 291767 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 291768 T808 C124 P18627 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 291768 T808 C124 P18627 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 291768 T709 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 291769 T709 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 291770 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 291799 T808 C124 P18627 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 291799 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 291800 T709 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 291801 T709 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 291802 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 291811 T747 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 292804 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 293121 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 293122 T732 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:18627_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18627/w/b"}
[junit4:junit4] 2> 293143 T731 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> 293144 T767 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> 293144 T801 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> 293144 T751 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> 293144 T738 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> 293143 T784 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> 293807 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 293814 T747 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 293814 T747 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:18627_w%252Fb&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 294810 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 295813 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C124_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18627_w%2Fb, base_url=http://127.0.0.1:18627/w/b}
[junit4:junit4] 2> 295816 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:26155/w/b/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 295816 T808 C124 P18627 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18627/w/b START replicas=[http://127.0.0.1:26155/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 295817 T808 C124 P18627 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 295817 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 295817 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 295818 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 295818 T808 C124 P18627 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 295818 T808 C124 P18627 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:26155/w/b/collection1/. core=collection1
[junit4:junit4] 2> 295818 T808 C124 P18627 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 295820 T743 C122 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 295831 T741 C122 P26155 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 295838 T741 C122 P26155 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 295839 T741 C122 P26155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 295840 T741 C122 P26155 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 295841 T741 C122 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 295842 T808 C124 P18627 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 295843 T808 C124 P18627 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 295846 T745 C122 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 295847 T808 C124 P18627 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 295848 T808 C124 P18627 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 295848 T808 C124 P18627 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 295852 T745 C122 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=2
[junit4:junit4] 2> 295853 T808 C124 P18627 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 295855 T808 C124 P18627 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index.20130624024314072
[junit4:junit4] 2> 295856 T808 C124 P18627 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index.20130624024314072 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1bffd008; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 295860 T745 C122 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 295862 T808 C124 P18627 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 295865 T808 C124 P18627 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 295865 T808 C124 P18627 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 295871 T808 C124 P18627 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 295871 T808 C124 P18627 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 295872 T808 C124 P18627 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 295873 T808 C124 P18627 oass.SolrIndexSearcher.<init> Opening Searcher@161022a6 main
[junit4:junit4] 2> 295874 T807 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@161022a6 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 295875 T808 C124 P18627 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index.20130624024314072 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index.20130624024314072;done=true>>]
[junit4:junit4] 2> 295875 T808 C124 P18627 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index.20130624024314072
[junit4:junit4] 2> 295876 T808 C124 P18627 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index.20130624024314072
[junit4:junit4] 2> 295877 T808 C124 P18627 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 295877 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 295878 T808 C124 P18627 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 295878 T808 C124 P18627 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 295880 T808 C124 P18627 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 296156 T732 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 296157 T732 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:18627_w%2Fb",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18627/w/b"}
[junit4:junit4] 2> 296173 T751 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> 296173 T738 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> 296173 T767 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> 296173 T801 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> 296173 T784 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> 296173 T731 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> 296816 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 296818 T709 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C125 name=collection1 org.apache.solr.core.SolrCore@950bde8 url=http://127.0.0.1:43020/w/b/collection1 node=127.0.0.1:43020_w%2Fb C125_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:43020_w%2Fb, base_url=http://127.0.0.1:43020/w/b, leader=true}
[junit4:junit4] 2> 296837 T721 C125 P43020 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 296845 T721 C125 P43020 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 296846 T721 C125 P43020 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 296866 T721 C125 P43020 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 296867 T721 C125 P43020 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 296870 T721 C125 P43020 oass.SolrIndexSearcher.<init> Opening Searcher@73244d80 main
[junit4:junit4] 2> 296871 T721 C125 P43020 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 296872 T735 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@73244d80 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 296872 T721 C125 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 35
[junit4:junit4] 2> ASYNC NEW_CORE C126 name=collection1 org.apache.solr.core.SolrCore@43095f4 url=http://127.0.0.1:18616/w/b/collection1 node=127.0.0.1:18616_w%2Fb C126_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18616_w%2Fb, base_url=http://127.0.0.1:18616/w/b}
[junit4:junit4] 2> 296899 T757 C126 P18616 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:26155/w/b/collection1/, StdNode: http://127.0.0.1:18616/w/b/collection1/, StdNode: http://127.0.0.1:18622/w/b/collection1/, StdNode: http://127.0.0.1:18627/w/b/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 296903 T744 C122 P26155 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 296903 T758 C126 P18616 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C124_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18627_w%2Fb, base_url=http://127.0.0.1:18627/w/b}
[junit4:junit4] 2> 296924 T791 C124 P18627 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C123_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18622_w%2Fb, base_url=http://127.0.0.1:18622/w/b}
[junit4:junit4] 2> 296924 T774 C123 P18622 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 296930 T744 C122 P26155 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 296930 T758 C126 P18616 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 296931 T758 C126 P18616 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> ASYNC NEW_CORE C127 name=collection1 org.apache.solr.core.SolrCore@19b3a8db url=http://127.0.0.1:26155/w/b/collection1 node=127.0.0.1:26155_w%2Fb C127_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26155_w%2Fb, base_url=http://127.0.0.1:26155/w/b, leader=true}
[junit4:junit4] 2> 296931 T744 C127 P26155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> ASYNC NEW_CORE C128 name=collection1 org.apache.solr.core.SolrCore@68e881a4 url=http://127.0.0.1:18622/w/b/collection1 node=127.0.0.1:18622_w%2Fb C128_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18622_w%2Fb, base_url=http://127.0.0.1:18622/w/b}
[junit4:junit4] 2> 296944 T774 C128 P18622 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 296946 T774 C128 P18622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> ASYNC NEW_CORE C129 name=collection1 org.apache.solr.core.SolrCore@47f15427 url=http://127.0.0.1:18627/w/b/collection1 node=127.0.0.1:18627_w%2Fb C129_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18627_w%2Fb, base_url=http://127.0.0.1:18627/w/b}
[junit4:junit4] 2> 296944 T791 C129 P18627 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 296946 T744 C127 P26155 oass.SolrIndexSearcher.<init> Opening Searcher@444c05c1 main
[junit4:junit4] 2> ASYNC NEW_CORE C130 name=collection1 org.apache.solr.core.SolrCore@43095f4 url=http://127.0.0.1:18616/w/b/collection1 node=127.0.0.1:18616_w%2Fb C130_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18616_w%2Fb, base_url=http://127.0.0.1:18616/w/b}
[junit4:junit4] 2> 296946 T758 C130 P18616 oass.SolrIndexSearcher.<init> Opening Searcher@424bd639 main
[junit4:junit4] 2> 296948 T744 C127 P26155 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 296949 T753 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@444c05c1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 296947 T791 C129 P18627 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 296949 T744 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 46
[junit4:junit4] 2> 296949 T769 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@424bd639 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 296948 T774 C128 P18622 oass.SolrIndexSearcher.<init> Opening Searcher@6d30f3f5 main
[junit4:junit4] 2> 296948 T758 C130 P18616 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 296951 T791 C129 P18627 oass.SolrIndexSearcher.<init> Opening Searcher@2f860a43 main
[junit4:junit4] 2> 296952 T786 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6d30f3f5 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 296951 T774 C128 P18622 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 296952 T791 C129 P18627 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 296951 T758 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 48
[junit4:junit4] 2> 296953 T807 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2f860a43 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 296953 T774 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 30
[junit4:junit4] 2> 296954 T791 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 31
[junit4:junit4] 2> 296956 T757 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 58
[junit4:junit4] 2> 296957 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 296961 T742 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 296964 T759 C130 P18616 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 296968 T775 C128 P18622 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 296971 T792 C129 P18627 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C131 name=collection1 org.apache.solr.core.SolrCore@950bde8 url=http://127.0.0.1:43020/w/b/collection1 node=127.0.0.1:43020_w%2Fb C131_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:43020_w%2Fb, base_url=http://127.0.0.1:43020/w/b, leader=true}
[junit4:junit4] 2> 298985 T721 C131 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438725960842084352)} 0 9
[junit4:junit4] 2> 298996 T793 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={update.distrib=FROMLEADER&_version_=-1438725960847327232&update.from=http://127.0.0.1:26155/w/b/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438725960847327232)} 0 3
[junit4:junit4] 2> 298997 T776 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={update.distrib=FROMLEADER&_version_=-1438725960847327232&update.from=http://127.0.0.1:26155/w/b/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438725960847327232)} 0 3
[junit4:junit4] 2> 298998 T760 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={update.distrib=FROMLEADER&_version_=-1438725960847327232&update.from=http://127.0.0.1:26155/w/b/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438725960847327232)} 0 4
[junit4:junit4] 2> 298999 T746 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438725960847327232)} 0 11
[junit4:junit4] 2> 299004 T721 C131 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {add=[0 (1438725960862007296)]} 0 2
[junit4:junit4] 2> 299016 T776 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438725960868298752)]} 0 3
[junit4:junit4] 2> 299017 T760 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438725960868298752)]} 0 4
[junit4:junit4] 2> 299018 T793 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438725960868298752)]} 0 5
[junit4:junit4] 2> 299019 T746 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {add=[0 (1438725960868298752)]} 0 12
[junit4:junit4] 2> 299024 T721 C131 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {add=[1 (1438725960885075968)]} 0 1
[junit4:junit4] 2> 299033 T760 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438725960889270272)]} 0 1
[junit4:junit4] 2> 299033 T776 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438725960889270272)]} 0 1
[junit4:junit4] 2> 299033 T793 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438725960889270272)]} 0 1
[junit4:junit4] 2> 299035 T746 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {add=[1 (1438725960889270272)]} 0 7
[junit4:junit4] 2> 299040 T721 C131 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {add=[2 (1438725960900804608)]} 0 2
[junit4:junit4] 2> 299047 T747 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:18616/w/b/collection1/]
[junit4:junit4] 2> 299047 T747 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18616/w/b/collection1/ against:[http://127.0.0.1:18616/w/b/collection1/] result:true
[junit4:junit4] 2> 299048 T747 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18622/w/b/collection1/ against:[http://127.0.0.1:18616/w/b/collection1/] result:false
[junit4:junit4] 2> 299048 T747 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18627/w/b/collection1/ against:[http://127.0.0.1:18616/w/b/collection1/] result:false
[junit4:junit4] 2> 299054 T793 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:18616/w/b/collection1/&wt=javabin&version=2} {add=[2 (1438725960910241792)]} 0 2
[junit4:junit4] 2> 299054 T776 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:18616/w/b/collection1/&wt=javabin&version=2} {add=[2 (1438725960910241792)]} 0 2
[junit4:junit4] 2> 299055 T747 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:18627/w/b/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:18616/w/b/collection1/&wt=javabin&version=2} {add=[2 (1438725960910241792)]} 0 9
[junit4:junit4] 2> 299056 T794 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={test.distrib.skip.servers=http://127.0.0.1:18616/w/b/collection1/&wt=javabin&version=2} {add=[2]} 0 13
[junit4:junit4] 2> 299061 T721 C131 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={wt=javabin&version=2} {add=[3 (1438725960922824704)]} 0 2
[junit4:junit4] 2> 299065 T746 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:18616/w/b/collection1/, http://127.0.0.1:18622/w/b/collection1/]
[junit4:junit4] 2> 299066 T746 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18616/w/b/collection1/ against:[http://127.0.0.1:18616/w/b/collection1/, http://127.0.0.1:18622/w/b/collection1/] result:true
[junit4:junit4] 2> 299067 T746 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18622/w/b/collection1/ against:[http://127.0.0.1:18616/w/b/collection1/, http://127.0.0.1:18622/w/b/collection1/] result:true
[junit4:junit4] 2> 299067 T746 C127 P26155 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18627/w/b/collection1/ against:[http://127.0.0.1:18616/w/b/collection1/, http://127.0.0.1:18622/w/b/collection1/] result:false
[junit4:junit4] 2> 299073 T793 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={distrib.from=http://127.0.0.1:26155/w/b/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:18616/w/b/collection1/&wt=javabin&version=2} {add=[3 (1438725960930164736)]} 0 1
[junit4:junit4] 2> 299075 T746 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={test.distrib.skip.servers=http://127.0.0.1:18616/w/b/collection1/&test.distrib.skip.servers=http://127.0.0.1:18622/w/b/collection1/&wt=javabin&version=2} {add=[3 (1438725960930164736)]} 0 10
[junit4:junit4] 2> 299078 T721 C131 P43020 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 299154 T721 C131 P43020 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 299155 T721 C131 P43020 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 299162 T721 C131 P43020 oass.SolrIndexSearcher.<init> Opening Searcher@f102963 main
[junit4:junit4] 2> 299163 T721 C131 P43020 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 299164 T735 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f102963 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 299165 T721 C131 P43020 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 87
[junit4:junit4] 2> 299170 T746 C127 P26155 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:26155/w/b/collection1/, StdNode: http://127.0.0.1:18616/w/b/collection1/, StdNode: http://127.0.0.1:18622/w/b/collection1/, StdNode: http://127.0.0.1:18627/w/b/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 299172 T741 C127 P26155 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 299174 T760 C130 P18616 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 299174 T793 C129 P18627 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 299174 T776 C128 P18622 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 299285 T741 C127 P26155 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@215bf054; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 299287 T741 C127 P26155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 299295 T741 C127 P26155 oass.SolrIndexSearcher.<init> Opening Searcher@78f334db main
[junit4:junit4] 2> 299296 T741 C127 P26155 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 299297 T753 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78f334db main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 299298 T741 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 126
[junit4:junit4] 2> 299299 T776 C128 P18622 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12969129; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 299300 T793 C129 P18627 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e800275; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 299300 T760 C130 P18616 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55b3a564; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 299300 T776 C128 P18622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 299301 T760 C130 P18616 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 299301 T793 C129 P18627 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 299312 T760 C130 P18616 oass.SolrIndexSearcher.<init> Opening Searcher@64a176c9 main
[junit4:junit4] 2> 299313 T793 C129 P18627 oass.SolrIndexSearcher.<init> Opening Searcher@780aac95 main
[junit4:junit4] 2> 299312 T776 C128 P18622 oass.SolrIndexSearcher.<init> Opening Searcher@5e653c33 main
[junit4:junit4] 2> 299314 T793 C129 P18627 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 299313 T760 C130 P18616 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 299315 T807 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@780aac95 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 299315 T776 C128 P18622 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 299315 T769 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64a176c9 main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):C2)}
[junit4:junit4] 2> 299316 T793 C129 P18627 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 142
[junit4:junit4] 2> 299316 T786 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e653c33 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):C3)}
[junit4:junit4] 2> 299317 T760 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 143
[junit4:junit4] 2> 299318 T776 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 144
[junit4:junit4] 2> 299319 T746 C127 P26155 oasup.LogUpdateProcessor.finish [collection1] webapp=/w/b path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 150
[junit4:junit4] 2> 299320 T709 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 299321 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 299322 T709 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 299326 T742 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 299330 T759 C130 P18616 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=1
[junit4:junit4] 2> 299334 T775 C128 P18622 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=1
[junit4:junit4] 2> 299338 T792 C129 P18627 oasc.SolrCore.execute [collection1] webapp=/w/b path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 299347 T709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 299375 T777 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 299376 T777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 299390 T821 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 299390 T821 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 299391 T821 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b START replicas=[http://127.0.0.1:18616/w/b/collection1/, http://127.0.0.1:18622/w/b/collection1/, http://127.0.0.1:18627/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 299394 T761 C130 P18616 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 299395 T795 C129 P18627 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 299396 T821 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b Received 3 versions from 127.0.0.1:18616/w/b/collection1/
[junit4:junit4] 2> 299394 T778 C128 P18622 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 299397 T821 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b Our versions are newer. ourLowThreshold=1438725960847327232 otherHigh=1438725960889270272
[junit4:junit4] 2> 299398 T821 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b Received 5 versions from 127.0.0.1:18627/w/b/collection1/
[junit4:junit4] 2> 299398 T821 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b Our versions are newer. ourLowThreshold=1438725960847327232 otherHigh=1438725960910241792
[junit4:junit4] 2> 299399 T821 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b Received 4 versions from 127.0.0.1:18622/w/b/collection1/
[junit4:junit4] 2> 299399 T821 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b Our versions are newer. ourLowThreshold=1438725960847327232 otherHigh=1438725960910241792
[junit4:junit4] 2> 299399 T821 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:26155/w/b DONE. sync succeeded
[junit4:junit4] 2> 299400 T821 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 299400 T821 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/: try and ask http://127.0.0.1:18616/w/b/collection1/ to sync
[junit4:junit4] 2> 299401 T821 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/: try and ask http://127.0.0.1:18622/w/b/collection1/ to sync
[junit4:junit4] 2> 299401 T821 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/: try and ask http://127.0.0.1:18627/w/b/collection1/ to sync
[junit4:junit4] 2> 299403 T762 C130 P18616 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18616/w/b START replicas=[http://127.0.0.1:26155/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 299403 T779 C128 P18622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18622/w/b START replicas=[http://127.0.0.1:26155/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 299404 T796 C129 P18627 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18627/w/b START replicas=[http://127.0.0.1:26155/w/b/collection1/] nUpdates=100
[junit4:junit4] 2> 299406 T831 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 299406 T832 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 299407 T779 C128 P18622 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18622/w/b Received 5 versions from 127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 299407 T743 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 299408 T779 C128 P18622 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:18622/w/b Requesting updates from 127.0.0.1:26155/w/b/collection1/n=1 versions=[1438725960930164736]
[junit4:junit4] 2> 299407 T796 C129 P18627 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18627/w/b Received 5 versions from 127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 299408 T762 C130 P18616 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18616/w/b Received 5 versions from 127.0.0.1:26155/w/b/collection1/
[junit4:junit4] 2> 299409 T796 C129 P18627 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18627/w/b Our versions are newer. ourLowThreshold=1438725960847327232 otherHigh=1438725960910241792
[junit4:junit4] 2> 299410 T762 C130 P18616 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:18616/w/b Requesting updates from 127.0.0.1:26155/w/b/collection1/n=2 versions=[1438725960930164736, 1438725960910241792]
[junit4:junit4] 2> 299410 T796 C129 P18627 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18627/w/b DONE. sync succeeded
[junit4:junit4] 2> 299411 T796 C129 P18627 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={sync=http://127.0.0.1:26155/w/b/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=7
[junit4:junit4] 2> 299412 T743 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={distrib=false&getUpdates=1438725960930164736&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 299412 T821 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/: sync completed with http://127.0.0.1:18627/w/b/collection1/
[junit4:junit4] 2> 299414 T832 C127 P26155 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={distrib=false&getUpdates=1438725960930164736,1438725960910241792&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 299417 T779 C128 P18622 oasup.LogUpdateProcessor.finish [collection1] {add=[3 (1438725960930164736)]} 0 4
[junit4:junit4] 2> 299418 T779 C128 P18622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18622/w/b DONE. sync succeeded
[junit4:junit4] 2> 299418 T779 C128 P18622 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={sync=http://127.0.0.1:26155/w/b/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=15
[junit4:junit4] 2> 299419 T821 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/: sync completed with http://127.0.0.1:18622/w/b/collection1/
[junit4:junit4] 2> 299420 T762 C130 P18616 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438725960910241792), 3 (1438725960930164736)]} 0 5
[junit4:junit4] 2> 299421 T762 C130 P18616 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18616/w/b DONE. sync succeeded
[junit4:junit4] 2> 299422 T762 C130 P18616 oasc.SolrCore.execute [collection1] webapp=/w/b path=/get params={sync=http://127.0.0.1:26155/w/b/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=19
[junit4:junit4] 2> 299423 T821 oasc.SyncStrategy.syncToMe http://127.0.0.1:26155/w/b/collection1/: sync completed with http://127.0.0.1:18616/w/b/collection1/
[junit4:junit4] 2> 299423 T821 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=33
[junit4:junit4] 2> 299424 T777 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=57
[junit4:junit4] 2> 299425 T709 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 299426 T709 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 299427 T709 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 299428 T709 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 299432 T721 C131 P43020 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 299442 T721 C131 P43020 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372075970787/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c8b3e08; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(or
[...truncated too long message...]
1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:26155_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:26155/w/b"},
[junit4:junit4] 1> "3":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:18616_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:18616/w/b"},
[junit4:junit4] 1> "4":{
[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:18622_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:18622/w/b"},
[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:18627_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:18627/w/b",
[junit4:junit4] 1> "leader":"true"}}}},
[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:43020_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43020/w/b",
[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:18627_w%2Fb (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:43020_w%2Fb (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:26155_w%2Fb (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:18622_w%2Fb (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/89920370822021132-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89920370822021134-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89920370822021130-4-n_0000000005 (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:18627_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:18627/w/b"}
[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/89920370822021123-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:43020_w%2Fb",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43020/w/b"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89920370822021132-127.0.0.1:18627_w%2Fb-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89920370822021134-127.0.0.1:26155_w%2Fb-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89920370822021130-127.0.0.1:18622_w%2Fb-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89920370822021123-127.0.0.1:43020_w%2Fb-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89920370822021123-127.0.0.1:43020_w%2Fb-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=C088980BD06DB6BB -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=th_TH -Dtests.timezone=Pacific/Marquesas -Dtests.file.encoding=ISO8859-1
[junit4:junit4] FAILURE 881s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:26155/w/b/collection1lastClient and got 248 from http://127.0.0.1:18622/w/b/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([C088980BD06DB6BB:416E1613A732D687]: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:679)
[junit4:junit4] 2> 1153924 T709 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Appending, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=th_TH, timezone=Pacific/Marquesas
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=221630240,total=425984000
[junit4:junit4] 2> NOTE: All tests run in this JVM: [UpdateRequestProcessorFactoryTest, CoreAdminHandlerTest, TestPropInjectDefaults, QueryEqualityTest, FastVectorHighlighterTest, WordBreakSolrSpellCheckerTest, RegexBoostProcessorTest, TestCharFilters, SpellingQueryConverterTest, CSVRequestHandlerTest, LoggingHandlerTest, DocumentBuilderTest, SuggesterFSTTest, MinimalSchemaTest, TestReloadAndDeleteDocs, TestQuerySenderListener, CacheHeaderTest, TestSolrCoreProperties, TestSchemaSimilarityResource, FileBasedSpellCheckerTest, TestCloudManagedSchemaAddField, TestSweetSpotSimilarityFactory, TestSearchPerf, QueryResultKeyTest, ClusterStateUpdateTest, UnloadDistributedZkTest, TestFuzzyAnalyzedSuggestions, TestPhraseSuggestions, PrimUtilsTest, TestPluginEnable, ShowFileRequestHandlerTest, TestReversedWildcardFilterFactory, AutoCommitTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 881.39s, 1 test, 1 failure <<< FAILURES!
[...truncated 706 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:392: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:372: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 14 ignored (8 assumptions)
Total time: 60 minutes 35 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure