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/27 01:28:06 UTC
[JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 297 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/297/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:17655/fg/bm/collection1lastClient and got 271 from http://127.0.0.1:41254/fg/bm/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:17655/fg/bm/collection1lastClient and got 271 from http://127.0.0.1:41254/fg/bm/collection1
at __randomizedtesting.SeedInfo.seed([6622FCAD1334659C:E7C472B5646B05A0]: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 9260 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 1385573 T3080 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /fg/bm
[junit4:junit4] 2> 1385577 T3080 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372287737142
[junit4:junit4] 2> 1385579 T3080 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1385580 T3081 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1385681 T3080 oasc.ZkTestServer.run start zk server on port:10364
[junit4:junit4] 2> 1385682 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1385714 T3087 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74c1adc5 name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1385714 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1385715 T3080 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1385783 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1385792 T3089 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bb92b47 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1385793 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1385793 T3080 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1385828 T3080 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1385852 T3080 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1385861 T3080 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1385864 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1385865 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1386012 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1386013 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1386116 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1386117 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1386121 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1386121 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1386145 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1386146 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1386150 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1386152 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1386202 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1386203 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1386207 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1386208 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1386251 T3080 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1386252 T3080 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1386607 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1386612 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:10367
[junit4:junit4] 2> 1386612 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1386613 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1386613 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885
[junit4:junit4] 2> 1386614 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/solr.xml
[junit4:junit4] 2> 1386614 T3080 oasc.CoreContainer.<init> New CoreContainer 732184017
[junit4:junit4] 2> 1386615 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/'
[junit4:junit4] 2> 1386616 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/'
[junit4:junit4] 2> 1386739 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1386740 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1386740 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1386741 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1386741 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1386742 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1386742 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1386743 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1386743 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1386744 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1386759 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1386760 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1386760 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1386761 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1386764 T3100 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e131e2b name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1386765 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1386767 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1386776 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1386778 T3102 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4feb6003 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1386778 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1386786 T3080 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1386790 T3080 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1386793 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1386796 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:10367_fg%2Fbm
[junit4:junit4] 2> 1386802 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:10367_fg%2Fbm
[junit4:junit4] 2> 1386805 T3080 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1386825 T3080 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1386834 T3080 oasc.Overseer.start Overseer (id=89934249141862403-127.0.0.1:10367_fg%2Fbm-n_0000000000) starting
[junit4:junit4] 2> 1386858 T3080 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1386862 T3104 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1386862 T3080 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1386865 T3080 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1386867 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1386869 T3103 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1386873 T3105 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1386874 T3105 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1388374 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1388375 T3103 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:10367_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10367/fg/bm"}
[junit4:junit4] 2> 1388375 T3103 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1388375 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1388389 T3102 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> 1388877 T3105 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/collection1
[junit4:junit4] 2> 1388877 T3105 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1388878 T3105 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1388878 T3105 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1388880 T3105 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/collection1/'
[junit4:junit4] 2> 1388881 T3105 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1388881 T3105 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/collection1/lib/README' to classloader
[junit4:junit4] 2> 1388936 T3105 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1388993 T3105 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1389095 T3105 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1389102 T3105 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1389707 T3105 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1389707 T3105 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1389708 T3105 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1389721 T3105 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1389725 T3105 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1389741 T3105 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1389746 T3105 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1389750 T3105 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1389751 T3105 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1389751 T3105 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1389751 T3105 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1389752 T3105 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1389753 T3105 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1389753 T3105 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1389753 T3105 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372287737885/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/control/data/
[junit4:junit4] 2> 1389754 T3105 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1389754 T3105 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1389756 T3105 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/control/data
[junit4:junit4] 2> 1389757 T3105 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/control/data/index/
[junit4:junit4] 2> 1389757 T3105 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1389758 T3105 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/control/data/index
[junit4:junit4] 2> 1389791 T3105 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@65535277; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1389791 T3105 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1389794 T3105 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1389794 T3105 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1389795 T3105 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1389795 T3105 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1389796 T3105 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1389796 T3105 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1389796 T3105 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1389797 T3105 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1389797 T3105 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1389807 T3105 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1389816 T3105 oass.SolrIndexSearcher.<init> Opening Searcher@4b4af69f main
[junit4:junit4] 2> 1389817 T3105 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1389817 T3105 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1389821 T3106 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4b4af69f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1389822 T3105 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1389822 T3105 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:10367/fg/bm collection:control_collection shard:shard1
[junit4:junit4] 2> 1389823 T3105 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1389840 T3105 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1389851 T3105 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1389852 T3105 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1389852 T3105 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:10367/fg/bm/collection1/
[junit4:junit4] 2> 1389852 T3105 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1389852 T3105 oasc.SyncStrategy.syncToMe http://127.0.0.1:10367/fg/bm/collection1/ has no replicas
[junit4:junit4] 2> 1389853 T3105 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:10367/fg/bm/collection1/
[junit4:junit4] 2> 1389853 T3105 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1389898 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1389923 T3102 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> 1389976 T3105 oasc.ZkController.register We are http://127.0.0.1:10367/fg/bm/collection1/ and leader is http://127.0.0.1:10367/fg/bm/collection1/
[junit4:junit4] 2> 1389976 T3105 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:10367/fg/bm
[junit4:junit4] 2> 1389976 T3105 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1389976 T3105 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1389977 T3105 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1389978 T3105 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1389979 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1389980 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1389981 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1389997 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1389999 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1390000 T3109 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2df8266d name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1390001 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1390002 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1390004 T3080 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1390266 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1390269 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:10373
[junit4:junit4] 2> 1390270 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1390270 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1390271 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569
[junit4:junit4] 2> 1390271 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/solr.xml
[junit4:junit4] 2> 1390272 T3080 oasc.CoreContainer.<init> New CoreContainer 1129795872
[junit4:junit4] 2> 1390272 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/'
[junit4:junit4] 2> 1390273 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/'
[junit4:junit4] 2> 1390383 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1390384 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1390385 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1390385 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1390385 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1390386 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1390386 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1390387 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1390387 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1390388 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1390405 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1390405 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1390406 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1390407 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1390410 T3120 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7303e42 name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1390410 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1390413 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1390424 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1390426 T3122 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17bd1c9 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1390426 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1390431 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1391429 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1391430 T3103 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:10367_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10367/fg/bm"}
[junit4:junit4] 2> 1391434 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:10373_fg%2Fbm
[junit4:junit4] 2> 1391444 T3122 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> 1391444 T3109 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> 1391444 T3102 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> 1391445 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:10373_fg%2Fbm
[junit4:junit4] 2> 1391456 T3122 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> 1391456 T3109 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> 1391456 T3102 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> 1391457 T3122 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1391458 T3109 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1391458 T3102 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1391464 T3123 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1391464 T3123 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1392949 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1392950 T3103 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:10373_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10373/fg/bm"}
[junit4:junit4] 2> 1392950 T3103 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 1392951 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1392965 T3122 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> 1392965 T3109 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> 1392965 T3102 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> 1393467 T3123 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/collection1
[junit4:junit4] 2> 1393467 T3123 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1393468 T3123 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1393468 T3123 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1393470 T3123 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/collection1/'
[junit4:junit4] 2> 1393471 T3123 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1393472 T3123 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/collection1/lib/README' to classloader
[junit4:junit4] 2> 1393521 T3123 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1393578 T3123 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1393680 T3123 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1393691 T3123 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1394298 T3123 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1394299 T3123 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1394299 T3123 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1394312 T3123 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1394316 T3123 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1394332 T3123 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1394336 T3123 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1394341 T3123 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1394342 T3123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1394342 T3123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1394343 T3123 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1394344 T3123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1394344 T3123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1394344 T3123 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1394345 T3123 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372287741569/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1/
[junit4:junit4] 2> 1394345 T3123 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1394345 T3123 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1394346 T3123 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1
[junit4:junit4] 2> 1394347 T3123 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1/index/
[junit4:junit4] 2> 1394348 T3123 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1394349 T3123 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1/index
[junit4:junit4] 2> 1394355 T3123 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@71678175; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1394356 T3123 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1394359 T3123 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1394359 T3123 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1394360 T3123 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1394360 T3123 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1394361 T3123 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1394361 T3123 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1394362 T3123 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1394362 T3123 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1394363 T3123 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1394372 T3123 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1394381 T3123 oass.SolrIndexSearcher.<init> Opening Searcher@761b4ef9 main
[junit4:junit4] 2> 1394382 T3123 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1394382 T3123 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1394386 T3124 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@761b4ef9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1394388 T3123 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1394388 T3123 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:10373/fg/bm collection:collection1 shard:shard1
[junit4:junit4] 2> 1394389 T3123 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1394405 T3123 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1394417 T3123 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1394417 T3123 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1394417 T3123 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1394418 T3123 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1394418 T3123 oasc.SyncStrategy.syncToMe http://127.0.0.1:10373/fg/bm/collection1/ has no replicas
[junit4:junit4] 2> 1394418 T3123 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1394418 T3123 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1394470 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1394478 T3122 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> 1394478 T3102 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> 1394478 T3109 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> 1394484 T3123 oasc.ZkController.register We are http://127.0.0.1:10373/fg/bm/collection1/ and leader is http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1394484 T3123 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:10373/fg/bm
[junit4:junit4] 2> 1394484 T3123 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1394484 T3123 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1394485 T3123 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1394486 T3123 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1394487 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1394488 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1394488 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1394760 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1394763 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:10380
[junit4:junit4] 2> 1394763 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1394764 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1394764 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069
[junit4:junit4] 2> 1394765 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/solr.xml
[junit4:junit4] 2> 1394765 T3080 oasc.CoreContainer.<init> New CoreContainer 99462076
[junit4:junit4] 2> 1394766 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/'
[junit4:junit4] 2> 1394767 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/'
[junit4:junit4] 2> 1394875 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1394875 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1394876 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1394876 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1394877 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1394877 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1394878 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1394878 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1394879 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1394879 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1394896 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1394896 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1394897 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1394898 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1394900 T3136 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d96e589 name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1394901 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1394917 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1394928 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1394930 T3138 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63839f48 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1394930 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1394941 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1395944 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:10380_fg%2Fbm
[junit4:junit4] 2> 1395985 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:10380_fg%2Fbm
[junit4:junit4] 2> 1395986 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1396011 T3102 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> 1396011 T3122 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> 1396011 T3109 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> 1396012 T3138 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1396012 T3103 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:10373_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10373/fg/bm"}
[junit4:junit4] 2> 1396020 T3122 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1396020 T3109 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1396025 T3139 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1396025 T3139 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1396067 T3103 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:10380_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10380/fg/bm"}
[junit4:junit4] 2> 1396067 T3103 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1396067 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1396085 T3109 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> 1396085 T3122 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> 1396085 T3138 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> 1396095 T3102 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1396095 T3102 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> 1397067 T3139 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/collection1
[junit4:junit4] 2> 1397067 T3139 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1397068 T3139 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1397068 T3139 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1397070 T3139 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/collection1/'
[junit4:junit4] 2> 1397071 T3139 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/collection1/lib/README' to classloader
[junit4:junit4] 2> 1397072 T3139 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1397122 T3139 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1397179 T3139 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1397280 T3139 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1397287 T3139 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1397895 T3139 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1397896 T3139 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1397897 T3139 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1397909 T3139 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1397914 T3139 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1397929 T3139 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1397933 T3139 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1397938 T3139 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1397939 T3139 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1397939 T3139 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1397939 T3139 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1397940 T3139 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1397941 T3139 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1397941 T3139 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1397941 T3139 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372287746069/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty2/
[junit4:junit4] 2> 1397941 T3139 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1397942 T3139 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1397943 T3139 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty2
[junit4:junit4] 2> 1397944 T3139 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty2/index/
[junit4:junit4] 2> 1397945 T3139 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1397946 T3139 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty2/index
[junit4:junit4] 2> 1397952 T3139 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7f498d30; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1397952 T3139 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1397955 T3139 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1397956 T3139 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1397956 T3139 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1397957 T3139 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1397958 T3139 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1397958 T3139 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1397958 T3139 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1397959 T3139 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1397959 T3139 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1397969 T3139 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1397978 T3139 oass.SolrIndexSearcher.<init> Opening Searcher@7d980afb main
[junit4:junit4] 2> 1397979 T3139 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1397979 T3139 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1397984 T3140 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7d980afb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1397985 T3139 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1397986 T3139 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:10380/fg/bm collection:collection1 shard:shard1
[junit4:junit4] 2> 1397989 T3139 oasc.ZkController.register We are http://127.0.0.1:10380/fg/bm/collection1/ and leader is http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1397989 T3139 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:10380/fg/bm
[junit4:junit4] 2> 1397989 T3139 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1397990 T3139 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1077 name=collection1 org.apache.solr.core.SolrCore@6e0708d7 url=http://127.0.0.1:10380/fg/bm/collection1 node=127.0.0.1:10380_fg%2Fbm C1077_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:10380_fg%2Fbm, base_url=http://127.0.0.1:10380/fg/bm}
[junit4:junit4] 2> 1397990 T3141 C1077 P10380 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1398006 T3141 C1077 P10380 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1398006 T3139 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1398006 T3141 C1077 P10380 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1398006 T3141 C1077 P10380 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1398007 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1398007 T3141 C1077 P10380 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1398008 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1398008 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1398029 T3112 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1398287 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1398290 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:10388
[junit4:junit4] 2> 1398291 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1398292 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1398292 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592
[junit4:junit4] 2> 1398293 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/solr.xml
[junit4:junit4] 2> 1398293 T3080 oasc.CoreContainer.<init> New CoreContainer 477557103
[junit4:junit4] 2> 1398294 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/'
[junit4:junit4] 2> 1398295 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/'
[junit4:junit4] 2> 1398405 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1398406 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1398407 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1398407 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1398408 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1398408 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1398409 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1398409 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1398410 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1398410 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1398425 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1398426 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1398426 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1398427 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1398430 T3153 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@534f1a4 name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1398431 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1398447 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1398457 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1398459 T3155 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f6dd0b5 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1398460 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1398471 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1399098 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1399099 T3103 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:10380_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10380/fg/bm"}
[junit4:junit4] 2> 1399104 T3102 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> 1399104 T3155 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> 1399104 T3138 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> 1399104 T3122 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> 1399104 T3109 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> 1399474 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:10388_fg%2Fbm
[junit4:junit4] 2> 1399476 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:10388_fg%2Fbm
[junit4:junit4] 2> 1399478 T3102 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> 1399478 T3122 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> 1399478 T3109 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> 1399478 T3138 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> 1399479 T3155 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1399479 T3155 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> 1399480 T3102 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1399480 T3122 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1399481 T3109 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1399481 T3138 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1399485 T3156 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1399486 T3156 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1400032 T3112 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1400032 T3112 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:10380_fg%252Fbm&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1400609 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1400610 T3103 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:10388_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10388/fg/bm"}
[junit4:junit4] 2> 1400610 T3103 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1400611 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1400624 T3102 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> 1400624 T3138 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> 1400624 T3109 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> 1400624 T3155 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> 1400624 T3122 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> 1401489 T3156 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/collection1
[junit4:junit4] 2> 1401489 T3156 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1401490 T3156 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1401490 T3156 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1401492 T3156 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/collection1/'
[junit4:junit4] 2> 1401493 T3156 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/collection1/lib/README' to classloader
[junit4:junit4] 2> 1401494 T3156 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1401544 T3156 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1401601 T3156 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1401702 T3156 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1401709 T3156 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1078 name=collection1 org.apache.solr.core.SolrCore@6e0708d7 url=http://127.0.0.1:10380/fg/bm/collection1 node=127.0.0.1:10380_fg%2Fbm C1078_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:10380_fg%2Fbm, base_url=http://127.0.0.1:10380/fg/bm}
[junit4:junit4] 2> 1402034 T3141 C1078 P10380 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:10373/fg/bm/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1402034 T3141 C1078 P10380 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:10380/fg/bm START replicas=[http://127.0.0.1:10373/fg/bm/collection1/] nUpdates=100
[junit4:junit4] 2> 1402035 T3141 C1078 P10380 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1402035 T3141 C1078 P10380 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1402036 T3141 C1078 P10380 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1402036 T3141 C1078 P10380 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1402036 T3141 C1078 P10380 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1402036 T3141 C1078 P10380 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:10373/fg/bm/collection1/. core=collection1
[junit4:junit4] 2> 1402037 T3141 C1078 P10380 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1079 name=collection1 org.apache.solr.core.SolrCore@5e9089d8 url=http://127.0.0.1:10373/fg/bm/collection1 node=127.0.0.1:10373_fg%2Fbm C1079_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:10373_fg%2Fbm, base_url=http://127.0.0.1:10373/fg/bm, leader=true}
[junit4:junit4] 2> 1402044 T3113 C1079 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1402047 T3114 C1079 P10373 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1402053 T3114 C1079 P10373 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@71678175; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1402053 T3114 C1079 P10373 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1402054 T3114 C1079 P10373 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 1402054 T3114 C1079 P10373 oass.SolrIndexSearcher.<init> Opening Searcher@5d93d925 realtime
[junit4:junit4] 2> 1402055 T3114 C1079 P10373 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1402055 T3114 C1079 P10373 oasup.LogUpdateProcessor.finish [collection1] webapp=/fg/bm path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 1402056 T3141 C1078 P10380 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1402056 T3141 C1078 P10380 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1402058 T3115 C1079 P10373 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1402059 T3115 C1079 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1402059 T3141 C1078 P10380 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1402059 T3141 C1078 P10380 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1402060 T3141 C1078 P10380 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1402060 T3141 C1078 P10380 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1402061 T3141 C1078 P10380 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1402128 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1402129 T3103 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:10380_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10380/fg/bm"}
[junit4:junit4] 2> 1402138 T3102 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> 1402138 T3122 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> 1402138 T3109 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> 1402138 T3138 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> 1402138 T3155 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> 1402322 T3156 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1402323 T3156 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1402324 T3156 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1402336 T3156 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1402341 T3156 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1402356 T3156 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1402360 T3156 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1402365 T3156 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1402366 T3156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1402366 T3156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1402366 T3156 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1402367 T3156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1402368 T3156 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1402368 T3156 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1402368 T3156 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372287749592/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty3/
[junit4:junit4] 2> 1402369 T3156 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1402369 T3156 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1402370 T3156 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty3
[junit4:junit4] 2> 1402371 T3156 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty3/index/
[junit4:junit4] 2> 1402372 T3156 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1402373 T3156 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty3/index
[junit4:junit4] 2> 1402379 T3156 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@54f33345; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1402380 T3156 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1402383 T3156 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1402383 T3156 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1402384 T3156 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1402384 T3156 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1402385 T3156 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1402385 T3156 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1402388 T3156 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1402389 T3156 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1402389 T3156 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1402398 T3156 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1402407 T3156 oass.SolrIndexSearcher.<init> Opening Searcher@145981ab main
[junit4:junit4] 2> 1402409 T3156 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1402409 T3156 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1402413 T3158 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@145981ab main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1402415 T3156 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1402415 T3156 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:10388/fg/bm collection:collection1 shard:shard1
[junit4:junit4] 2> 1402418 T3156 oasc.ZkController.register We are http://127.0.0.1:10388/fg/bm/collection1/ and leader is http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1402419 T3156 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:10388/fg/bm
[junit4:junit4] 2> 1402419 T3156 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1402419 T3156 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1080 name=collection1 org.apache.solr.core.SolrCore@46d58621 url=http://127.0.0.1:10388/fg/bm/collection1 node=127.0.0.1:10388_fg%2Fbm C1080_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:10388_fg%2Fbm, base_url=http://127.0.0.1:10388/fg/bm}
[junit4:junit4] 2> 1402419 T3159 C1080 P10388 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1402420 T3159 C1080 P10388 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1402420 T3156 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1402420 T3159 C1080 P10388 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1402421 T3159 C1080 P10388 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1402421 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1402422 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1402422 T3159 C1080 P10388 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1402423 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1402447 T3116 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1402707 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1402710 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:10396
[junit4:junit4] 2> 1402711 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1402711 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1402712 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010
[junit4:junit4] 2> 1402712 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/solr.xml
[junit4:junit4] 2> 1402713 T3080 oasc.CoreContainer.<init> New CoreContainer 272096330
[junit4:junit4] 2> 1402714 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/'
[junit4:junit4] 2> 1402714 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/'
[junit4:junit4] 2> 1402822 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1402823 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1402823 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1402824 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1402824 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1402825 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1402825 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1402826 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1402826 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1402827 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1402843 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1402844 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1402844 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1402845 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1402848 T3171 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@347d460f name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1402849 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1402864 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1402875 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1402877 T3173 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a8afb33 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1402877 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1402887 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1403649 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1403650 T3103 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:10388_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10388/fg/bm"}
[junit4:junit4] 2> 1403655 T3173 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> 1403655 T3138 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> 1403655 T3109 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> 1403655 T3102 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> 1403655 T3155 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> 1403655 T3122 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> 1403891 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:10396_fg%2Fbm
[junit4:junit4] 2> 1403893 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:10396_fg%2Fbm
[junit4:junit4] 2> 1403895 T3102 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> 1403895 T3109 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> 1403896 T3155 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1403895 T3138 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> 1403895 T3122 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> 1403896 T3155 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> 1403896 T3173 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1403897 T3173 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> 1403897 T3102 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1403897 T3109 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1403906 T3138 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1403907 T3122 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1403911 T3174 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1403912 T3174 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1404449 T3116 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1404449 T3116 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:10388_fg%252Fbm&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 1405160 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1405161 T3103 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:10396_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10396/fg/bm"}
[junit4:junit4] 2> 1405162 T3103 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1405162 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1405166 T3102 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> 1405166 T3173 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> 1405166 T3155 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> 1405166 T3109 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> 1405166 T3138 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> 1405166 T3122 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> 1405915 T3174 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/collection1
[junit4:junit4] 2> 1405915 T3174 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1405916 T3174 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1405916 T3174 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1405918 T3174 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/collection1/'
[junit4:junit4] 2> 1405919 T3174 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/collection1/lib/README' to classloader
[junit4:junit4] 2> 1405920 T3174 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1405970 T3174 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1406032 T3174 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1406134 T3174 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1406141 T3174 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1081 name=collection1 org.apache.solr.core.SolrCore@46d58621 url=http://127.0.0.1:10388/fg/bm/collection1 node=127.0.0.1:10388_fg%2Fbm C1081_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:10388_fg%2Fbm, base_url=http://127.0.0.1:10388/fg/bm}
[junit4:junit4] 2> 1406451 T3159 C1081 P10388 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:10373/fg/bm/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1406451 T3159 C1081 P10388 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:10388/fg/bm START replicas=[http://127.0.0.1:10373/fg/bm/collection1/] nUpdates=100
[junit4:junit4] 2> 1406452 T3159 C1081 P10388 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1406452 T3159 C1081 P10388 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1406452 T3159 C1081 P10388 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1406452 T3159 C1081 P10388 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1406452 T3159 C1081 P10388 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1406453 T3159 C1081 P10388 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:10373/fg/bm/collection1/. core=collection1
[junit4:junit4] 2> 1406453 T3159 C1081 P10388 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1082 name=collection1 org.apache.solr.core.SolrCore@5e9089d8 url=http://127.0.0.1:10373/fg/bm/collection1 node=127.0.0.1:10373_fg%2Fbm C1082_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:10373_fg%2Fbm, base_url=http://127.0.0.1:10373/fg/bm, leader=true}
[junit4:junit4] 2> 1406454 T3113 C1082 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1406463 T3117 C1082 P10373 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1406464 T3117 C1082 P10373 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 1406465 T3117 C1082 P10373 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1406466 T3117 C1082 P10373 oasup.LogUpdateProcessor.finish [collection1] webapp=/fg/bm path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 1406466 T3159 C1081 P10388 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1406467 T3159 C1081 P10388 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1406469 T3115 C1082 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1406469 T3159 C1081 P10388 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1406470 T3159 C1081 P10388 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1406470 T3159 C1081 P10388 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1406470 T3159 C1081 P10388 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1406484 T3159 C1081 P10388 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1406670 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1406671 T3103 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:10388_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10388/fg/bm"}
[junit4:junit4] 2> 1406684 T3102 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> 1406685 T3109 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> 1406685 T3155 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> 1406685 T3138 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> 1406685 T3122 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> 1406685 T3173 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> 1406752 T3174 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1406753 T3174 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1406754 T3174 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1406767 T3174 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1406771 T3174 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1406787 T3174 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1406792 T3174 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1406796 T3174 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1406797 T3174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1406798 T3174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1406798 T3174 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1406799 T3174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1406799 T3174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1406800 T3174 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1406800 T3174 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372287754010/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty4/
[junit4:junit4] 2> 1406800 T3174 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1406801 T3174 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1406802 T3174 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty4
[junit4:junit4] 2> 1406803 T3174 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty4/index/
[junit4:junit4] 2> 1406803 T3174 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1406804 T3174 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty4/index
[junit4:junit4] 2> 1406811 T3174 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d23f9c7; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1406811 T3174 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1406814 T3174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1406815 T3174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1406815 T3174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1406816 T3174 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1406817 T3174 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1406817 T3174 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1406820 T3174 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1406820 T3174 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1406821 T3174 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1406830 T3174 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1406839 T3174 oass.SolrIndexSearcher.<init> Opening Searcher@42f160b2 main
[junit4:junit4] 2> 1406841 T3174 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1406841 T3174 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1406846 T3176 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@42f160b2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1406848 T3174 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1406848 T3174 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:10396/fg/bm collection:collection1 shard:shard1
[junit4:junit4] 2> 1406852 T3174 oasc.ZkController.register We are http://127.0.0.1:10396/fg/bm/collection1/ and leader is http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1406852 T3174 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:10396/fg/bm
[junit4:junit4] 2> 1406852 T3174 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1406852 T3174 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1083 name=collection1 org.apache.solr.core.SolrCore@7c1ce9d2 url=http://127.0.0.1:10396/fg/bm/collection1 node=127.0.0.1:10396_fg%2Fbm C1083_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:10396_fg%2Fbm, base_url=http://127.0.0.1:10396/fg/bm}
[junit4:junit4] 2> 1406853 T3177 C1083 P10396 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1406853 T3177 C1083 P10396 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1406853 T3174 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1406853 T3177 C1083 P10396 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1406854 T3177 C1083 P10396 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1406855 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1406855 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1406856 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1406860 T3177 C1083 P10396 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1406873 T3118 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1407131 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1407134 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:28525
[junit4:junit4] 2> 1407135 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1407136 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1407136 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436
[junit4:junit4] 2> 1407137 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/solr.xml
[junit4:junit4] 2> 1407137 T3080 oasc.CoreContainer.<init> New CoreContainer 2085647256
[junit4:junit4] 2> 1407138 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/'
[junit4:junit4] 2> 1407138 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/'
[junit4:junit4] 2> 1407248 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1407249 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1407249 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1407250 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1407250 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1407251 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1407251 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1407252 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1407252 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1407253 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1407268 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1407268 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1407269 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1407270 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1407272 T3189 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7357604a name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1407273 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1407275 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1407285 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1407287 T3191 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b23a087 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1407287 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1407292 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1408189 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1408190 T3103 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:10396_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10396/fg/bm"}
[junit4:junit4] 2> 1408202 T3173 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> 1408202 T3109 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> 1408202 T3155 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> 1408202 T3122 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> 1408202 T3191 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> 1408202 T3102 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> 1408202 T3138 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> 1408295 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:28525_fg%2Fbm
[junit4:junit4] 2> 1408297 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:28525_fg%2Fbm
[junit4:junit4] 2> 1408299 T3138 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> 1408300 T3109 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> 1408300 T3173 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408299 T3102 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> 1408299 T3122 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> 1408300 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1408300 T3155 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408300 T3191 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408301 T3109 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408301 T3138 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408301 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1408302 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1408308 T3102 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408308 T3122 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 1408314 T3192 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1408314 T3192 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1408875 T3118 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1408875 T3118 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:10396_fg%252Fbm&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 1409707 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1409708 T3103 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[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:28525_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28525/fg/bm"}
[junit4:junit4] 2> 1409708 T3103 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1409708 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1409721 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1409721 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1409721 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1409721 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1409721 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1409721 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1409721 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1410318 T3192 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/collection1
[junit4:junit4] 2> 1410318 T3192 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1410319 T3192 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1410319 T3192 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1410321 T3192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/collection1/'
[junit4:junit4] 2> 1410322 T3192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/collection1/lib/README' to classloader
[junit4:junit4] 2> 1410322 T3192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1410377 T3192 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1410435 T3192 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1410437 T3192 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1410444 T3192 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1084 name=collection1 org.apache.solr.core.SolrCore@7c1ce9d2 url=http://127.0.0.1:10396/fg/bm/collection1 node=127.0.0.1:10396_fg%2Fbm C1084_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:10396_fg%2Fbm, base_url=http://127.0.0.1:10396/fg/bm}
[junit4:junit4] 2> 1410877 T3177 C1084 P10396 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:10373/fg/bm/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1410877 T3177 C1084 P10396 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:10396/fg/bm START replicas=[http://127.0.0.1:10373/fg/bm/collection1/] nUpdates=100
[junit4:junit4] 2> 1410878 T3177 C1084 P10396 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1410878 T3177 C1084 P10396 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1410878 T3177 C1084 P10396 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1410878 T3177 C1084 P10396 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1410879 T3177 C1084 P10396 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1410879 T3177 C1084 P10396 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:10373/fg/bm/collection1/. core=collection1
[junit4:junit4] 2> 1410879 T3177 C1084 P10396 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1085 name=collection1 org.apache.solr.core.SolrCore@5e9089d8 url=http://127.0.0.1:10373/fg/bm/collection1 node=127.0.0.1:10373_fg%2Fbm C1085_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:10373_fg%2Fbm, base_url=http://127.0.0.1:10373/fg/bm, leader=true}
[junit4:junit4] 2> 1410880 T3113 C1085 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1410891 T3112 C1085 P10373 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1410891 T3112 C1085 P10373 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 1410892 T3112 C1085 P10373 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1410893 T3112 C1085 P10373 oasup.LogUpdateProcessor.finish [collection1] webapp=/fg/bm path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 2
[junit4:junit4] 2> 1410894 T3177 C1084 P10396 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1410894 T3177 C1084 P10396 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1410896 T3115 C1085 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1410897 T3177 C1084 P10396 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1410897 T3177 C1084 P10396 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1410897 T3177 C1084 P10396 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1410897 T3177 C1084 P10396 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1410899 T3177 C1084 P10396 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1411058 T3192 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1411059 T3192 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1411059 T3192 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1411072 T3192 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1411076 T3192 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1411091 T3192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1411096 T3192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1411100 T3192 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1411102 T3192 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1411102 T3192 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1411102 T3192 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1411103 T3192 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1411104 T3192 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1411104 T3192 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1411104 T3192 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372287758436/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty5/
[junit4:junit4] 2> 1411104 T3192 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1411105 T3192 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1411106 T3192 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty5
[junit4:junit4] 2> 1411107 T3192 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty5/index/
[junit4:junit4] 2> 1411108 T3192 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1411108 T3192 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty5/index
[junit4:junit4] 2> 1411125 T3192 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty5/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@73dc8cec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1411125 T3192 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1411128 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1411129 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1411129 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1411130 T3192 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1411131 T3192 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1411131 T3192 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1411134 T3192 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1411134 T3192 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1411135 T3192 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1411144 T3192 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1411153 T3192 oass.SolrIndexSearcher.<init> Opening Searcher@3356ae1a main
[junit4:junit4] 2> 1411155 T3192 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1411155 T3192 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1411159 T3194 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3356ae1a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1411161 T3192 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1411161 T3192 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:28525/fg/bm collection:collection1 shard:shard1
[junit4:junit4] 2> 1411169 T3192 oasc.ZkController.register We are http://127.0.0.1:28525/fg/bm/collection1/ and leader is http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1411169 T3192 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:28525/fg/bm
[junit4:junit4] 2> 1411169 T3192 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1411170 T3192 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1086 name=collection1 org.apache.solr.core.SolrCore@ee68f61 url=http://127.0.0.1:28525/fg/bm/collection1 node=127.0.0.1:28525_fg%2Fbm C1086_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:28525_fg%2Fbm, base_url=http://127.0.0.1:28525/fg/bm}
[junit4:junit4] 2> 1411170 T3195 C1086 P28525 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1411171 T3195 C1086 P28525 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1411171 T3192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1411171 T3195 C1086 P28525 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1411171 T3195 C1086 P28525 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1411172 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1411173 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1411173 T3195 C1086 P28525 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1411173 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1411197 T3114 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1411225 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1411226 T3103 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:10396_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:10396/fg/bm"}
[junit4:junit4] 2> 1411241 T3103 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[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:28525_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28525/fg/bm"}
[junit4:junit4] 2> 1411253 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411253 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411253 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411253 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411253 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411253 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411253 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1411456 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1411459 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:17655
[junit4:junit4] 2> 1411460 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1411460 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1411461 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759
[junit4:junit4] 2> 1411461 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/solr.xml
[junit4:junit4] 2> 1411462 T3080 oasc.CoreContainer.<init> New CoreContainer 1369717444
[junit4:junit4] 2> 1411462 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/'
[junit4:junit4] 2> 1411463 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/'
[junit4:junit4] 2> 1411576 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1411577 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1411577 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1411578 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1411578 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1411579 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1411579 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1411580 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1411580 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1411581 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1411595 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1411596 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1411596 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1411597 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1411600 T3207 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7708deb8 name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1411601 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1411603 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1411613 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1411622 T3209 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51ba2e96 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1411622 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1411626 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1412198 T3114 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1412198 T3114 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:28525_fg%252Fbm&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 1412630 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:17655_fg%2Fbm
[junit4:junit4] 2> 1412657 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:17655_fg%2Fbm
[junit4:junit4] 2> 1412660 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1412662 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1412662 T3173 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412662 T3209 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412660 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1412660 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4] 2> 1412662 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412662 T3155 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412662 T3191 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412664 T3109 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412663 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412664 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412664 T3122 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412673 T3102 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412673 T3138 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 1412678 T3210 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1412678 T3210 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1412759 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1412760 T3103 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[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:17655_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:17655/fg/bm"}
[junit4:junit4] 2> 1412760 T3103 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1412760 T3103 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1412765 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412766 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412766 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412766 T3209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412766 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412765 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412765 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1412765 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1413684 T3210 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/collection1
[junit4:junit4] 2> 1413684 T3210 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1413685 T3210 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1413685 T3210 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1413687 T3210 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/collection1/'
[junit4:junit4] 2> 1413688 T3210 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1413689 T3210 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/collection1/lib/README' to classloader
[junit4:junit4] 2> 1413740 T3210 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1413798 T3210 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1413899 T3210 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1413906 T3210 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1087 name=collection1 org.apache.solr.core.SolrCore@ee68f61 url=http://127.0.0.1:28525/fg/bm/collection1 node=127.0.0.1:28525_fg%2Fbm C1087_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:28525_fg%2Fbm, base_url=http://127.0.0.1:28525/fg/bm}
[junit4:junit4] 2> 1414200 T3195 C1087 P28525 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:10373/fg/bm/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1414200 T3195 C1087 P28525 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:28525/fg/bm START replicas=[http://127.0.0.1:10373/fg/bm/collection1/] nUpdates=100
[junit4:junit4] 2> 1414201 T3195 C1087 P28525 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1414201 T3195 C1087 P28525 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1414201 T3195 C1087 P28525 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1414201 T3195 C1087 P28525 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1414201 T3195 C1087 P28525 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1414201 T3195 C1087 P28525 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:10373/fg/bm/collection1/. core=collection1
[junit4:junit4] 2> 1414202 T3195 C1087 P28525 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1088 name=collection1 org.apache.solr.core.SolrCore@5e9089d8 url=http://127.0.0.1:10373/fg/bm/collection1 node=127.0.0.1:10373_fg%2Fbm C1088_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:10373_fg%2Fbm, base_url=http://127.0.0.1:10373/fg/bm, leader=true}
[junit4:junit4] 2> 1414204 T3113 C1088 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1414212 T3116 C1088 P10373 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1414212 T3116 C1088 P10373 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 1414214 T3116 C1088 P10373 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1414214 T3116 C1088 P10373 oasup.LogUpdateProcessor.finish [collection1] webapp=/fg/bm path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 2
[junit4:junit4] 2> 1414215 T3195 C1087 P28525 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1414215 T3195 C1087 P28525 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1414217 T3115 C1088 P10373 oasc.SolrCore.execute [collection1] webapp=/fg/bm path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1414217 T3195 C1087 P28525 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1414218 T3195 C1087 P28525 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1414218 T3195 C1087 P28525 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1414218 T3195 C1087 P28525 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1414220 T3195 C1087 P28525 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1414270 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1414271 T3103 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[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:28525_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28525/fg/bm"}
[junit4:junit4] 2> 1414275 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414275 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414276 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414276 T3209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414276 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414275 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414275 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414275 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1414505 T3210 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1414505 T3210 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1414506 T3210 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1414514 T3210 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1414517 T3210 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1414530 T3210 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1414533 T3210 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1414536 T3210 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1414537 T3210 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1414537 T3210 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1414538 T3210 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1414538 T3210 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1414539 T3210 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1414539 T3210 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1414539 T3210 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372287762759/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/
[junit4:junit4] 2> 1414539 T3210 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e1bdb58
[junit4:junit4] 2> 1414540 T3210 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1414540 T3210 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6
[junit4:junit4] 2> 1414541 T3210 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index/
[junit4:junit4] 2> 1414541 T3210 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1414542 T3210 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index
[junit4:junit4] 2> 1414547 T3210 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-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d66bbbd; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1414547 T3210 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1414549 T3210 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1414549 T3210 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1414550 T3210 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1414550 T3210 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1414551 T3210 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1414551 T3210 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1414554 T3210 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1414554 T3210 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1414554 T3210 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1414560 T3210 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1414566 T3210 oass.SolrIndexSearcher.<init> Opening Searcher@48d961b8 main
[junit4:junit4] 2> 1414567 T3210 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1414567 T3210 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1414571 T3212 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@48d961b8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1414572 T3210 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1414572 T3210 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:17655/fg/bm collection:collection1 shard:shard1
[junit4:junit4] 2> 1414576 T3210 oasc.ZkController.register We are http://127.0.0.1:17655/fg/bm/collection1/ and leader is http://127.0.0.1:10373/fg/bm/collection1/
[junit4:junit4] 2> 1414576 T3210 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:17655/fg/bm
[junit4:junit4] 2> 1414576 T3210 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1414576 T3210 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1089 name=collection1 org.apache.solr.core.SolrCore@463849d url=http://127.0.0.1:17655/fg/bm/collection1 node=127.0.0.1:17655_fg%2Fbm C1089_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:17655_fg%2Fbm, base_url=http://127.0.0.1:17655/fg/bm}
[junit4:junit4] 2> 1414577 T3213 C1089 P17655 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1414577 T3213 C1089 P17655 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1414577 T3210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1414577 T3213 C1089 P17655 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1414578 T3213 C1089 P17655 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1414578 T3080 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1414579 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1414579 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1414579 T3213 C1089 P17655 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1414596 T3117 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1414762 T3080 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1414764 T3080 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:41254
[junit4:junit4] 2> 1414765 T3080 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1414765 T3080 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1414765 T3080 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty7-1372287766158
[junit4:junit4] 2> 1414766 T3080 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty7-1372287766158/solr.xml
[junit4:junit4] 2> 1414766 T3080 oasc.CoreContainer.<init> New CoreContainer 1526739623
[junit4:junit4] 2> 1414767 T3080 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty7-1372287766158/'
[junit4:junit4] 2> 1414767 T3080 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty7-1372287766158/'
[junit4:junit4] 2> 1414838 T3080 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1414839 T3080 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1414839 T3080 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1414840 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1414840 T3080 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1414840 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1414841 T3080 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1414841 T3080 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1414841 T3080 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1414842 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1414852 T3080 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1414853 T3080 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:10364/solr
[junit4:junit4] 2> 1414853 T3080 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1414854 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1414857 T3225 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a3bd9c8 name:ZooKeeperConnection Watcher:127.0.0.1:10364 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1414857 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1414869 T3080 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1414881 T3080 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1414883 T3227 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a715f11 name:ZooKeeperConnection Watcher:127.0.0.1:10364/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1414883 T3080 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1414892 T3080 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1415781 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1415782 T3103 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[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:17655_fg%2Fbm",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:17655/fg/bm"}
[junit4:junit4] 2> 1415873 T3227 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415873 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415916 T3080 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41254_fg%2Fbm
[junit4:junit4] 2> 1415918 T3080 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41254_fg%2Fbm
[junit4:junit4] 2> 1415921 T3122 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415921 T3109 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415922 T3191 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415922 T3209 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415921 T3102 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415921 T3138 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4] 2> 1415922 T3209 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 1415922 T3191 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 1415923 T3122 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415922 T3155 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415922 T3173 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415921 T3227 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415924 T3173 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 1415924 T3155 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 1415924 T3227 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4] 2> 1415948 T3109 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415949 T3102 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415949 T3138 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 1415957 T3228 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1415957 T3228 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1416599 T3117 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1416599 T3117 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:17655_fg%252Fbm&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1417419 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKee
[...truncated too long message...]
junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=6622FCAD1334659C -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=ko -Dtests.timezone=America/Belize -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 556s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:17655/fg/bm/collection1lastClient and got 271 from http://127.0.0.1:41254/fg/bm/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([6622FCAD1334659C:E7C472B5646B05A0]: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> 1941993 T3080 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 1942968 T3227 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1942968 T3227 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> 1942969 T3227 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1969539 T3209 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:17655/fg/bm couldn't connect to http://127.0.0.1:28525/fg/bm/collection1/, counting as success
[junit4:junit4] 2> 1969539 T3209 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:17655/fg/bm DONE. sync succeeded
[junit4:junit4] 2> 1969540 T3209 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 1969540 T3209 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 1969540 T3209 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@463849d
[junit4:junit4] 2> 1969541 T3209 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=30,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=305,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1969542 T3209 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1969542 T3209 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1969542 T3209 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1969545 T3209 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1969547 T3209 oasc.CachingDirectoryFactory.close Closing NRTCachingDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1969547 T3209 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index;done=false>>]
[junit4:junit4] 2> 1969547 T3209 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6/index
[junit4:junit4] 2> 1969547 T3209 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6;done=false>>]
[junit4:junit4] 2> 1969548 T3209 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372287737142/jetty6
[junit4:junit4] 2> 1969548 T3209 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1969548 T3209 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> 1969548 T3209 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1969549 T3209 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=ko, timezone=America/Belize
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=202391256,total=410779648
[junit4:junit4] 2> NOTE: All tests run in this JVM: [BasicDistributedZkTest, DocValuesTest, SliceStateUpdateTest, TestQuerySenderListener, TestRemoteStreaming, ZkCLITest, OverseerCollectionProcessorTest, TestRandomDVFaceting, ZkControllerTest, IndexSchemaTest, ClusterStateUpdateTest, DistributedTermsComponentTest, DistributedSpellCheckComponentTest, TestReplicationHandler, MBeansHandlerTest, AnalysisAfterCoreReloadTest, MinimalSchemaTest, TestSort, TestSchemaSimilarityResource, TestLMDirichletSimilarityFactory, TestBadConfig, TestSweetSpotSimilarityFactory, SliceStateTest, QueryResultKeyTest, ChaosMonkeyNothingIsSafeTest, TestFieldCollectionResource, TestSurroundQueryParser, TestPhraseSuggestions, PrimitiveFieldTypeTest, LukeRequestHandlerTest, DocumentBuilderTest, TestXIncludeConfig, DirectSolrConnectionTest, SystemInfoHandlerTest, RecoveryZkTest, TestSolrIndexConfig, PluginInfoTest, TestSolrQueryParser, PrimUtilsTest, SoftAutoCommitTest, SchemaVersionSpecificBehaviorTest, TestLFUCache, BadComponentTest, TestWriterPerf, QueryParsingTest, TestSolrDeletionPolicy2, LeaderElectionTest, TestConfig, BasicFunctionalityTest, TestSearchPerf, PreAnalyzedFieldTest, TestPseudoReturnFields, TestCollationKeyRangeQueries, SolrIndexSplitterTest, TestCloudManagedSchema, ReturnFieldsTest, TestPropInjectDefaults, TestStressRecovery, TestIBSimilarityFactory, PeerSyncTest, TestPHPSerializedResponseWriter, BadCopyFieldTest, QueryEqualityTest, SuggesterTest, FastVectorHighlighterTest, SolrInfoMBeanTest, AliasIntegrationTest, BinaryUpdateRequestHandlerTest, TestValueSourceCache, TestManagedSchema, CoreAdminHandlerTest, CacheHeaderTest, WordBreakSolrSpellCheckerTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 584.48s, 1 test, 1 failure <<< FAILURES!
[...truncated 463 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:399: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:372: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 11 ignored (5 assumptions)
Total time: 133 minutes 39 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure