You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/25 11:02:29 UTC
[JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 301 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/301/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:53280/ewd/vg/collection1lastClient and got 270 from http://127.0.0.1:17100/ewd/vg/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:53280/ewd/vg/collection1lastClient and got 270 from http://127.0.0.1:17100/ewd/vg/collection1
at __randomizedtesting.SeedInfo.seed([69D08E243E27E6FE:E836003C497886C2]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9313 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 101340 T652 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /ewd/vg
[junit4:junit4] 2> 101348 T652 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372148393422
[junit4:junit4] 2> 101349 T652 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 101350 T653 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 101451 T652 oasc.ZkTestServer.run start zk server on port:39616
[junit4:junit4] 2> 101452 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 101456 T659 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f680367 name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 101457 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 101457 T652 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 101480 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 101482 T661 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@640a1d2c name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 101482 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 101483 T652 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 101493 T652 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 101496 T652 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 101498 T652 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 101501 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 101536 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 101549 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 101550 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 101712 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 101713 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 101716 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 101717 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 101719 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 101720 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 101728 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 101729 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 101732 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 101733 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 101736 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 101737 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 101740 T652 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 101740 T652 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 102716 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 103007 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:34693
[junit4:junit4] 2> 103056 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 103057 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 103057 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824
[junit4:junit4] 2> 103058 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/solr.xml
[junit4:junit4] 2> 103058 T652 oasc.CoreContainer.<init> New CoreContainer 1398186809
[junit4:junit4] 2> 103059 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/'
[junit4:junit4] 2> 103059 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/'
[junit4:junit4] 2> 103212 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 103213 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 103213 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 103213 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 103214 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 103214 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 103214 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 103215 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 103215 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 103271 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 103814 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 103815 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 103825 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 103826 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 103832 T674 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@957546f name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 103833 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 103839 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 103854 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 103857 T676 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@140517d name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 103857 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 103860 T652 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 103872 T652 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 103876 T652 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 103878 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34693_ewd%2Fvg
[junit4:junit4] 2> 103885 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34693_ewd%2Fvg
[junit4:junit4] 2> 103888 T652 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 103901 T652 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 103911 T652 oasc.Overseer.start Overseer (id=89925117111762947-127.0.0.1:34693_ewd%2Fvg-n_0000000000) starting
[junit4:junit4] 2> 103923 T652 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 103927 T678 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 103928 T652 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 103937 T652 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 103939 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 103941 T677 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 103985 T679 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 103986 T679 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 105445 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 105446 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34693_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34693/ewd/vg"}
[junit4:junit4] 2> 105446 T677 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 105447 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 105465 T676 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> 105990 T679 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/collection1
[junit4:junit4] 2> 105990 T679 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 105991 T679 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 105992 T679 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 105995 T679 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/collection1/'
[junit4:junit4] 2> 105997 T679 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/collection1/lib/README' to classloader
[junit4:junit4] 2> 105998 T679 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 106108 T679 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 106185 T679 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 106287 T679 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 106350 T679 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 107100 T679 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 107115 T679 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 107117 T679 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 107153 T679 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 107170 T679 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 107174 T679 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 107179 T679 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 107180 T679 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 107180 T679 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 107181 T679 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 107181 T679 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 107182 T679 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 107220 T679 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148393824/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148393421/control/data/
[junit4:junit4] 2> 107220 T679 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2b06f1
[junit4:junit4] 2> 107221 T679 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 107256 T679 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/control/data
[junit4:junit4] 2> 107257 T679 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148393421/control/data/index/
[junit4:junit4] 2> 107257 T679 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148393421/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 107258 T679 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/control/data/index
[junit4:junit4] 2> 107270 T679 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-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5fb8002; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 107270 T679 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 107273 T679 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 107273 T679 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 107274 T679 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 107275 T679 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 107275 T679 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 107275 T679 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 107275 T679 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 107276 T679 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 107276 T679 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 107289 T679 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 107303 T679 oass.SolrIndexSearcher.<init> Opening Searcher@2dc09c8 main
[junit4:junit4] 2> 107304 T679 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 107304 T679 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 107307 T680 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2dc09c8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 107308 T679 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 107308 T679 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34693/ewd/vg collection:control_collection shard:shard1
[junit4:junit4] 2> 107320 T679 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 107337 T679 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 107354 T679 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 107365 T679 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 107365 T679 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 107366 T679 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34693/ewd/vg/collection1/
[junit4:junit4] 2> 107366 T679 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 107366 T679 oasc.SyncStrategy.syncToMe http://127.0.0.1:34693/ewd/vg/collection1/ has no replicas
[junit4:junit4] 2> 107366 T679 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34693/ewd/vg/collection1/
[junit4:junit4] 2> 107367 T679 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 108472 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 108559 T676 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> 108611 T679 oasc.ZkController.register We are http://127.0.0.1:34693/ewd/vg/collection1/ and leader is http://127.0.0.1:34693/ewd/vg/collection1/
[junit4:junit4] 2> 108611 T679 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34693/ewd/vg
[junit4:junit4] 2> 108611 T679 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 108612 T679 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 108612 T679 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 108614 T679 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 108622 T652 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 108622 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 108730 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 108759 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 108767 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108772 T683 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ef64195 name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 108773 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 108774 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 108779 T652 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 109067 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 109071 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:20971
[junit4:junit4] 2> 109072 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 109072 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 109073 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852
[junit4:junit4] 2> 109073 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/solr.xml
[junit4:junit4] 2> 109073 T652 oasc.CoreContainer.<init> New CoreContainer 901051255
[junit4:junit4] 2> 109074 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/'
[junit4:junit4] 2> 109075 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/'
[junit4:junit4] 2> 109225 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 109226 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 109226 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 109227 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 109227 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 109228 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 109228 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 109229 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 109229 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 109230 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 109251 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 109252 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 109252 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 109253 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 109281 T694 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50ebd722 name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 109282 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 109297 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 109311 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 109313 T696 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31b87d8c name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 109313 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 109327 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 110079 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 110080 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34693_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34693_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34693/ewd/vg"}
[junit4:junit4] 2> 110122 T676 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> 110122 T696 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> 110122 T683 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> 110331 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:20971_ewd%2Fvg
[junit4:junit4] 2> 110333 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:20971_ewd%2Fvg
[junit4:junit4] 2> 110336 T676 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> 110336 T683 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 110337 T696 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 110337 T683 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> 110337 T696 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> 110338 T676 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 110355 T697 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 110355 T697 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 111627 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 111628 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:20971_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:20971/ewd/vg"}
[junit4:junit4] 2> 111629 T677 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 111629 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 111645 T676 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> 111645 T696 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> 111645 T683 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> 112359 T697 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/collection1
[junit4:junit4] 2> 112359 T697 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 112360 T697 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 112360 T697 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 112362 T697 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/collection1/'
[junit4:junit4] 2> 112364 T697 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/collection1/lib/README' to classloader
[junit4:junit4] 2> 112364 T697 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 112425 T697 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 112489 T697 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 112590 T697 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 112653 T697 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 113274 T697 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 113295 T697 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 113299 T697 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 113327 T697 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 113334 T697 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 113339 T697 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 113340 T697 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 113341 T697 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 113341 T697 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 113342 T697 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 113343 T697 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 113343 T697 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 113343 T697 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148400852/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/
[junit4:junit4] 2> 113344 T697 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2b06f1
[junit4:junit4] 2> 113344 T697 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 113346 T697 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1
[junit4:junit4] 2> 113347 T697 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index/
[junit4:junit4] 2> 113347 T697 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 113348 T697 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index
[junit4:junit4] 2> 113356 T697 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-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 113356 T697 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 113360 T697 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 113360 T697 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 113361 T697 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 113362 T697 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 113363 T697 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 113363 T697 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 113363 T697 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 113364 T697 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 113364 T697 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 113381 T697 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 113392 T697 oass.SolrIndexSearcher.<init> Opening Searcher@6127c65c main
[junit4:junit4] 2> 113393 T697 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 113393 T697 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 113398 T698 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6127c65c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 113401 T697 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 113402 T697 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:20971/ewd/vg collection:collection1 shard:shard1
[junit4:junit4] 2> 113403 T697 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 113487 T697 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 113516 T697 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 113516 T697 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 113517 T697 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 113517 T697 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 113518 T697 oasc.SyncStrategy.syncToMe http://127.0.0.1:20971/ewd/vg/collection1/ has no replicas
[junit4:junit4] 2> 113518 T697 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 113518 T697 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 114652 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 114678 T676 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> 114678 T696 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> 114678 T683 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> 114713 T697 oasc.ZkController.register We are http://127.0.0.1:20971/ewd/vg/collection1/ and leader is http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 114713 T697 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:20971/ewd/vg
[junit4:junit4] 2> 114713 T697 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 114714 T697 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 114714 T697 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 114717 T697 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 114718 T652 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 114718 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 114719 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 114974 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 114977 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:32666
[junit4:junit4] 2> 114977 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 114978 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 114978 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809
[junit4:junit4] 2> 114979 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/solr.xml
[junit4:junit4] 2> 114979 T652 oasc.CoreContainer.<init> New CoreContainer 1640127732
[junit4:junit4] 2> 114980 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/'
[junit4:junit4] 2> 114980 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/'
[junit4:junit4] 2> 115088 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 115088 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 115089 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 115089 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 115090 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 115090 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 115090 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 115091 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 115091 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 115091 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 115107 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 115108 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 115108 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 115109 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 115112 T710 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f19bdcd name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 115112 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 115125 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 115137 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 115139 T712 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7733e13f name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 115140 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 115150 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 116154 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:32666_ewd%2Fvg
[junit4:junit4] 2> 116156 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:32666_ewd%2Fvg
[junit4:junit4] 2> 116159 T676 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> 116159 T683 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 116159 T712 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 116159 T696 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 116160 T683 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> 116160 T696 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> 116160 T676 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 116174 T713 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 116174 T713 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 116183 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 116184 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:20971_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:20971_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:20971/ewd/vg"}
[junit4:junit4] 2> 116188 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:32666_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32666/ewd/vg"}
[junit4:junit4] 2> 116189 T677 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 116189 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 116200 T676 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> 116200 T683 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> 116200 T696 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> 116200 T712 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> 117177 T713 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/collection1
[junit4:junit4] 2> 117177 T713 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 117178 T713 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 117178 T713 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 117180 T713 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/collection1/'
[junit4:junit4] 2> 117182 T713 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/collection1/lib/README' to classloader
[junit4:junit4] 2> 117183 T713 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 117250 T713 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 117309 T713 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 117410 T713 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 117463 T713 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 118098 T713 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 118119 T713 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 118124 T713 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 118150 T713 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 118156 T713 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 118162 T713 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 118163 T713 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 118163 T713 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 118164 T713 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 118165 T713 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 118165 T713 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 118165 T713 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 118166 T713 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148406809/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/
[junit4:junit4] 2> 118166 T713 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2b06f1
[junit4:junit4] 2> 118167 T713 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 118168 T713 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2
[junit4:junit4] 2> 118169 T713 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index/
[junit4:junit4] 2> 118170 T713 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 118171 T713 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index
[junit4:junit4] 2> 118179 T713 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-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e52acf0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 118179 T713 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 118184 T713 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 118184 T713 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 118185 T713 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 118186 T713 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 118187 T713 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 118187 T713 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 118188 T713 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 118188 T713 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 118189 T713 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 118208 T713 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 118219 T713 oass.SolrIndexSearcher.<init> Opening Searcher@1e9f5eeb main
[junit4:junit4] 2> 118220 T713 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 118221 T713 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 118225 T714 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e9f5eeb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 118228 T713 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 118228 T713 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:32666/ewd/vg collection:collection1 shard:shard1
[junit4:junit4] 2> 118236 T713 oasc.ZkController.register We are http://127.0.0.1:32666/ewd/vg/collection1/ and leader is http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 118236 T713 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:32666/ewd/vg
[junit4:junit4] 2> 118236 T713 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 118237 T713 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C120 name=collection1 org.apache.solr.core.SolrCore@400dd5ee url=http://127.0.0.1:32666/ewd/vg/collection1 node=127.0.0.1:32666_ewd%2Fvg C120_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:32666_ewd%2Fvg, base_url=http://127.0.0.1:32666/ewd/vg}
[junit4:junit4] 2> 118246 T715 C120 P32666 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 118247 T713 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 118247 T715 C120 P32666 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 118247 T715 C120 P32666 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 118247 T715 C120 P32666 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 118248 T652 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 118248 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 118249 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 118249 T715 C120 P32666 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 118641 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 118644 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:38439
[junit4:junit4] 2> 118645 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 118645 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 118646 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350
[junit4:junit4] 2> 118646 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/solr.xml
[junit4:junit4] 2> 118647 T652 oasc.CoreContainer.<init> New CoreContainer 1251517961
[junit4:junit4] 2> 118648 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/'
[junit4:junit4] 2> 118648 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/'
[junit4:junit4] 2> 118825 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 118826 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 118826 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 118826 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 118827 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 118827 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 118828 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 118828 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 118829 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 118829 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 118852 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 118853 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 118853 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 118854 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 118858 T727 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@303317a5 name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 118858 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 118869 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 118883 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 118886 T729 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3fa48382 name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 118886 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 118895 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 119216 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 119217 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:32666_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:32666_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32666/ewd/vg"}
[junit4:junit4] 2> 119229 T712 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> 119230 T676 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> 119229 T729 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> 119229 T683 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> 119229 T696 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> 119662 T686 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:32666_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 119664 T686 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:32666_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 0 seconds.
[junit4:junit4] 2> 119666 T686 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:32666_ewd%252Fvg_collection1&state=recovering&nodeName=127.0.0.1:32666_ewd%252Fvg&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=10
[junit4:junit4] 2> 119899 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38439_ewd%2Fvg
[junit4:junit4] 2> 119902 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38439_ewd%2Fvg
[junit4:junit4] 2> 119904 T676 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> 119905 T696 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119905 T683 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119905 T729 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119905 T712 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119908 T729 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> 119907 T683 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> 119906 T696 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> 119908 T712 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> 119921 T676 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 119932 T730 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 119932 T730 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 120734 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 120736 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38439_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38439/ewd/vg"}
[junit4:junit4] 2> 120737 T677 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 120737 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 120785 T712 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> 120785 T696 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> 120785 T729 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> 120785 T683 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> 120785 T676 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> 120935 T730 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/collection1
[junit4:junit4] 2> 120935 T730 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 120936 T730 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 120937 T730 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 120939 T730 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/collection1/'
[junit4:junit4] 2> 120941 T730 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/collection1/lib/README' to classloader
[junit4:junit4] 2> 120943 T730 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 121059 T730 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 121136 T730 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 121237 T730 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 121272 T730 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C121 name=collection1 org.apache.solr.core.SolrCore@400dd5ee url=http://127.0.0.1:32666/ewd/vg/collection1 node=127.0.0.1:32666_ewd%2Fvg C121_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:32666_ewd%2Fvg, base_url=http://127.0.0.1:32666/ewd/vg}
[junit4:junit4] 2> 121842 T715 C121 P32666 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:20971/ewd/vg/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 121863 T715 C121 P32666 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 121892 T715 C121 P32666 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:32666/ewd/vg START replicas=[http://127.0.0.1:20971/ewd/vg/collection1/] nUpdates=100
[junit4:junit4] 2> 121908 T715 C121 P32666 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 121909 T715 C121 P32666 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 121909 T715 C121 P32666 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 121909 T715 C121 P32666 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 121909 T715 C121 P32666 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 121910 T715 C121 P32666 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:20971/ewd/vg/collection1/. core=collection1
[junit4:junit4] 2> 121910 T715 C121 P32666 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C122 name=collection1 org.apache.solr.core.SolrCore@2660fd4b url=http://127.0.0.1:20971/ewd/vg/collection1 node=127.0.0.1:20971_ewd%2Fvg C122_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:20971_ewd%2Fvg, base_url=http://127.0.0.1:20971/ewd/vg, leader=true}
[junit4:junit4] 2> 121982 T687 C122 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=9
[junit4:junit4] 2> 122006 T730 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 122022 T730 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 122026 T730 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 122028 T688 C122 P20971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 122035 T688 C122 P20971 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-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 122035 T688 C122 P20971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 122040 T688 C122 P20971 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 122041 T688 C122 P20971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 122042 T688 C122 P20971 oass.SolrIndexSearcher.<init> Opening Searcher@1a09681 realtime
[junit4:junit4] 2> 122043 T688 C122 P20971 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 122043 T688 C122 P20971 oasup.LogUpdateProcessor.finish [collection1] webapp=/ewd/vg path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 70
[junit4:junit4] 2> 122044 T730 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 122073 T730 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 122077 T730 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 122078 T730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 122079 T730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 122079 T730 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 122080 T730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 122080 T730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 122080 T730 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 122080 T730 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148410350/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/
[junit4:junit4] 2> 122081 T730 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2b06f1
[junit4:junit4] 2> 122081 T730 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 122082 T730 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3
[junit4:junit4] 2> 122083 T730 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index/
[junit4:junit4] 2> 122084 T730 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 122085 T730 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index
[junit4:junit4] 2> 122101 T730 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-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7adf74f0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 122101 T730 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 122105 T730 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 122106 T730 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 122106 T730 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 122107 T730 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 122108 T730 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 122108 T730 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 122108 T730 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 122109 T730 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 122109 T730 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 122129 T730 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> ASYNC NEW_CORE C123 name=collection1 org.apache.solr.core.SolrCore@400dd5ee url=http://127.0.0.1:32666/ewd/vg/collection1 node=127.0.0.1:32666_ewd%2Fvg C123_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:32666_ewd%2Fvg, base_url=http://127.0.0.1:32666/ewd/vg}
[junit4:junit4] 2> 122134 T715 C123 P32666 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 122134 T715 C123 P32666 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 122140 T730 oass.SolrIndexSearcher.<init> Opening Searcher@7dc377b2 main
[junit4:junit4] 2> 122141 T730 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 122142 T730 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 122146 T732 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7dc377b2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 122149 T730 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 122149 T730 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38439/ewd/vg collection:collection1 shard:shard1
[junit4:junit4] 2> 122153 T730 oasc.ZkController.register We are http://127.0.0.1:38439/ewd/vg/collection1/ and leader is http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 122153 T730 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38439/ewd/vg
[junit4:junit4] 2> 122153 T730 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 122153 T730 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C124 name=collection1 org.apache.solr.core.SolrCore@1c370f59 url=http://127.0.0.1:38439/ewd/vg/collection1 node=127.0.0.1:38439_ewd%2Fvg C124_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:38439_ewd%2Fvg, base_url=http://127.0.0.1:38439/ewd/vg}
[junit4:junit4] 2> 122154 T733 C124 P38439 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 122154 T730 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 122155 T733 C124 P38439 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 122155 T733 C124 P38439 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 122155 T733 C124 P38439 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 122155 T652 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 122156 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 122156 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 122157 T733 C124 P38439 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 122165 T715 C123 P32666 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 122174 T690 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:38439_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 122222 T689 C122 P20971 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 122223 T689 C122 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=56
[junit4:junit4] 2> 122224 T715 C123 P32666 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 122224 T715 C123 P32666 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 122225 T715 C123 P32666 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 122229 T689 C122 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 122230 T715 C123 P32666 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 122232 T715 C123 P32666 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index.20130625052014304
[junit4:junit4] 2> 122233 T715 C123 P32666 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index.20130625052014304 lockFactory=org.apache.lucene.store.NativeFSLockFactory@365902df; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 122248 T689 C122 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=6
[junit4:junit4] 2> 122262 T715 C123 P32666 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 122270 T715 C123 P32666 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 122271 T715 C123 P32666 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 122281 T715 C123 P32666 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e52acf0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e52acf0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 122282 T715 C123 P32666 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 122283 T715 C123 P32666 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 122284 T715 C123 P32666 oass.SolrIndexSearcher.<init> Opening Searcher@5432b035 main
[junit4:junit4] 2> 122285 T714 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5432b035 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 122286 T715 C123 P32666 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index.20130625052014304 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index.20130625052014304;done=true>>]
[junit4:junit4] 2> 122286 T715 C123 P32666 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index.20130625052014304
[junit4:junit4] 2> 122287 T715 C123 P32666 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty2/index.20130625052014304
[junit4:junit4] 2> 122290 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 122290 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38439_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38439_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38439/ewd/vg"}
[junit4:junit4] 2> 122295 T715 C123 P32666 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 122295 T715 C123 P32666 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 122296 T715 C123 P32666 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 122296 T715 C123 P32666 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 122304 T712 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> 122304 T683 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> 122304 T676 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> 122304 T696 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> 122306 T715 C123 P32666 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 122304 T729 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> 122377 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 122379 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24101
[junit4:junit4] 2> 122380 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 122380 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 122380 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241
[junit4:junit4] 2> 122381 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/solr.xml
[junit4:junit4] 2> 122381 T652 oasc.CoreContainer.<init> New CoreContainer 1970837374
[junit4:junit4] 2> 122381 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/'
[junit4:junit4] 2> 122382 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/'
[junit4:junit4] 2> 122473 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 122474 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 122474 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 122474 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 122475 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 122475 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 122475 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 122476 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 122476 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 122476 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 122489 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 122489 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 122489 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 122490 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 122493 T746 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78b9027f name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 122494 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 122495 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 122503 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 122506 T748 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b8b0614 name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 122506 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 122517 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 123176 T690 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:38439_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 123176 T690 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:38439_ewd%252Fvg_collection1&state=recovering&nodeName=127.0.0.1:38439_ewd%252Fvg&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 123520 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24101_ewd%2Fvg
[junit4:junit4] 2> 123523 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24101_ewd%2Fvg
[junit4:junit4] 2> 123561 T676 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> 123561 T683 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123561 T696 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123561 T683 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> 123561 T748 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123561 T729 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123561 T712 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123562 T729 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> 123562 T696 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> 123563 T676 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 123562 T712 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> 123570 T749 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 123570 T749 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 123811 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 123811 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:32666_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:32666_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32666/ewd/vg"}
[junit4:junit4] 2> 123841 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:24101_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24101/ewd/vg"}
[junit4:junit4] 2> 123841 T677 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 123841 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 123855 T683 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> 123855 T748 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> 123855 T696 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> 123855 T729 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> 123855 T676 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> 123855 T712 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> 124584 T749 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/collection1
[junit4:junit4] 2> 124584 T749 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 124585 T749 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 124585 T749 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 124587 T749 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/collection1/'
[junit4:junit4] 2> 124588 T749 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/collection1/lib/README' to classloader
[junit4:junit4] 2> 124589 T749 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 124642 T749 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 124700 T749 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 124802 T749 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 124829 T749 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C125 name=collection1 org.apache.solr.core.SolrCore@1c370f59 url=http://127.0.0.1:38439/ewd/vg/collection1 node=127.0.0.1:38439_ewd%2Fvg C125_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:38439_ewd%2Fvg, base_url=http://127.0.0.1:38439/ewd/vg}
[junit4:junit4] 2> 125178 T733 C125 P38439 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:20971/ewd/vg/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 125178 T733 C125 P38439 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38439/ewd/vg START replicas=[http://127.0.0.1:20971/ewd/vg/collection1/] nUpdates=100
[junit4:junit4] 2> 125180 T733 C125 P38439 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 125180 T733 C125 P38439 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 125180 T733 C125 P38439 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 125180 T733 C125 P38439 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 125181 T733 C125 P38439 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 125181 T733 C125 P38439 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:20971/ewd/vg/collection1/. core=collection1
[junit4:junit4] 2> 125181 T733 C125 P38439 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C126 name=collection1 org.apache.solr.core.SolrCore@2660fd4b url=http://127.0.0.1:20971/ewd/vg/collection1 node=127.0.0.1:20971_ewd%2Fvg C126_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:20971_ewd%2Fvg, base_url=http://127.0.0.1:20971/ewd/vg, leader=true}
[junit4:junit4] 2> 125183 T687 C126 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 125196 T691 C126 P20971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 125203 T691 C126 P20971 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 125203 T691 C126 P20971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 125205 T691 C126 P20971 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 125205 T691 C126 P20971 oasup.LogUpdateProcessor.finish [collection1] webapp=/ewd/vg path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 125207 T733 C125 P38439 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 125207 T733 C125 P38439 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 125211 T689 C126 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 125212 T733 C125 P38439 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 125212 T733 C125 P38439 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 125213 T733 C125 P38439 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 125217 T689 C126 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 125218 T733 C125 P38439 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 125220 T733 C125 P38439 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index.20130625052017291
[junit4:junit4] 2> 125221 T733 C125 P38439 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index.20130625052017291 lockFactory=org.apache.lucene.store.NativeFSLockFactory@627a972; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 125226 T689 C126 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 125228 T733 C125 P38439 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 125232 T733 C125 P38439 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 125232 T733 C125 P38439 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 125239 T733 C125 P38439 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7adf74f0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7adf74f0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 125240 T733 C125 P38439 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 125240 T733 C125 P38439 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 125242 T733 C125 P38439 oass.SolrIndexSearcher.<init> Opening Searcher@514c678b main
[junit4:junit4] 2> 125243 T732 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@514c678b main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 125244 T733 C125 P38439 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index.20130625052017291 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index.20130625052017291;done=true>>]
[junit4:junit4] 2> 125244 T733 C125 P38439 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index.20130625052017291
[junit4:junit4] 2> 125244 T733 C125 P38439 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty3/index.20130625052017291
[junit4:junit4] 2> 125246 T733 C125 P38439 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 125246 T733 C125 P38439 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 125246 T733 C125 P38439 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 125246 T733 C125 P38439 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 125248 T733 C125 P38439 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 125368 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 125369 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38439_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38439_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38439/ewd/vg"}
[junit4:junit4] 2> 125384 T712 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> 125384 T748 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> 125384 T729 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> 125384 T676 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> 125384 T696 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> 125384 T683 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> 125491 T749 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 125510 T749 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 125514 T749 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 125540 T749 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 125565 T749 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 125570 T749 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 125571 T749 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 125572 T749 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 125572 T749 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 125573 T749 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 125574 T749 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 125574 T749 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 125574 T749 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148414241/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/
[junit4:junit4] 2> 125575 T749 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2b06f1
[junit4:junit4] 2> 125575 T749 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 125577 T749 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4
[junit4:junit4] 2> 125578 T749 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index/
[junit4:junit4] 2> 125579 T749 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 125580 T749 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index
[junit4:junit4] 2> 125587 T749 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-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4151d21e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 125588 T749 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 125591 T749 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 125592 T749 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 125593 T749 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 125593 T749 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 125594 T749 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 125594 T749 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 125611 T749 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 125612 T749 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 125612 T749 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 125632 T749 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 125642 T749 oass.SolrIndexSearcher.<init> Opening Searcher@44c5392a main
[junit4:junit4] 2> 125644 T749 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 125644 T749 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 125649 T752 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44c5392a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 125652 T749 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 125652 T749 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24101/ewd/vg collection:collection1 shard:shard1
[junit4:junit4] 2> 125656 T749 oasc.ZkController.register We are http://127.0.0.1:24101/ewd/vg/collection1/ and leader is http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 125657 T749 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24101/ewd/vg
[junit4:junit4] 2> 125657 T749 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 125657 T749 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C127 name=collection1 org.apache.solr.core.SolrCore@52ccc0d7 url=http://127.0.0.1:24101/ewd/vg/collection1 node=127.0.0.1:24101_ewd%2Fvg C127_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:24101_ewd%2Fvg, base_url=http://127.0.0.1:24101/ewd/vg}
[junit4:junit4] 2> 125657 T753 C127 P24101 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 125658 T753 C127 P24101 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 125658 T749 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 125658 T753 C127 P24101 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 125659 T753 C127 P24101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 125660 T652 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 125660 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 125661 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 125666 T753 C127 P24101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 125686 T692 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:24101_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 125965 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 125968 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53280
[junit4:junit4] 2> 125969 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 125970 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 125970 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755
[junit4:junit4] 2> 125971 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/solr.xml
[junit4:junit4] 2> 125971 T652 oasc.CoreContainer.<init> New CoreContainer 556822194
[junit4:junit4] 2> 125972 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/'
[junit4:junit4] 2> 125972 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/'
[junit4:junit4] 2> 126110 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 126111 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 126111 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 126112 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 126112 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 126113 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 126113 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 126114 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 126114 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 126115 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 126133 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 126134 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 126134 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 126135 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 126138 T765 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f9e3384 name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 126139 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 126151 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 126163 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 126166 T767 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@781fee0d name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 126166 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 126178 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 126889 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 126890 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:24101_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:24101_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24101/ewd/vg"}
[junit4:junit4] 2> 126905 T767 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 126905 T676 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> 126905 T712 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> 126905 T729 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> 126906 T748 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> 126905 T696 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> 126905 T683 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> 127181 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53280_ewd%2Fvg
[junit4:junit4] 2> 127183 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53280_ewd%2Fvg
[junit4:junit4] 2> 127186 T767 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> 127186 T676 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> 127186 T696 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127186 T748 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127186 T683 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127187 T748 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> 127187 T729 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127186 T696 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> 127186 T712 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127188 T676 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127188 T767 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 127187 T729 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> 127187 T683 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> 127188 T712 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> 127202 T768 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 127202 T768 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 127688 T692 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:24101_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 127688 T692 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:24101_ewd%252Fvg_collection1&state=recovering&nodeName=127.0.0.1:24101_ewd%252Fvg&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 128410 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 128411 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53280_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53280/ewd/vg"}
[junit4:junit4] 2> 128412 T677 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 128412 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 128486 T683 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> 128486 T748 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> 128486 T729 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> 128486 T696 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> 128486 T712 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> 128486 T676 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> 128486 T767 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> 129206 T768 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/collection1
[junit4:junit4] 2> 129206 T768 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 129207 T768 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 129207 T768 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 129209 T768 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/collection1/'
[junit4:junit4] 2> 129211 T768 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 129211 T768 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/collection1/lib/README' to classloader
[junit4:junit4] 2> 129270 T768 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 129337 T768 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 129339 T768 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 129365 T768 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C128 name=collection1 org.apache.solr.core.SolrCore@52ccc0d7 url=http://127.0.0.1:24101/ewd/vg/collection1 node=127.0.0.1:24101_ewd%2Fvg C128_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:24101_ewd%2Fvg, base_url=http://127.0.0.1:24101/ewd/vg}
[junit4:junit4] 2> 129690 T753 C128 P24101 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:20971/ewd/vg/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 129690 T753 C128 P24101 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:24101/ewd/vg START replicas=[http://127.0.0.1:20971/ewd/vg/collection1/] nUpdates=100
[junit4:junit4] 2> 129691 T753 C128 P24101 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 129691 T753 C128 P24101 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 129691 T753 C128 P24101 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 129691 T753 C128 P24101 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 129691 T753 C128 P24101 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> ASYNC NEW_CORE C129 name=collection1 org.apache.solr.core.SolrCore@52ccc0d7 url=http://127.0.0.1:24101/ewd/vg/collection1 node=127.0.0.1:24101_ewd%2Fvg C129_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:24101_ewd%2Fvg, base_url=http://127.0.0.1:24101/ewd/vg}
[junit4:junit4] 2> 129697 T753 C129 P24101 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:20971/ewd/vg/collection1/. core=collection1
[junit4:junit4] 2> 129697 T753 C129 P24101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C130 name=collection1 org.apache.solr.core.SolrCore@2660fd4b url=http://127.0.0.1:20971/ewd/vg/collection1 node=127.0.0.1:20971_ewd%2Fvg C130_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:20971_ewd%2Fvg, base_url=http://127.0.0.1:20971/ewd/vg, leader=true}
[junit4:junit4] 2> 129700 T687 C130 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 129712 T686 C130 P20971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 129718 T686 C130 P20971 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 129719 T686 C130 P20971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 129720 T686 C130 P20971 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 129720 T686 C130 P20971 oasup.LogUpdateProcessor.finish [collection1] webapp=/ewd/vg 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> 129722 T753 C129 P24101 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 129722 T753 C129 P24101 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 129726 T689 C130 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 129727 T753 C129 P24101 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 129727 T753 C129 P24101 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 129727 T753 C129 P24101 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 129732 T689 C130 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 129733 T753 C129 P24101 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 129735 T753 C129 P24101 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index.20130625052021806
[junit4:junit4] 2> 129736 T753 C129 P24101 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index.20130625052021806 lockFactory=org.apache.lucene.store.NativeFSLockFactory@dbe0560; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 129741 T689 C130 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 129743 T753 C129 P24101 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 129747 T753 C129 P24101 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 129747 T753 C129 P24101 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 129754 T753 C129 P24101 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4151d21e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4151d21e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 129755 T753 C129 P24101 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 129756 T753 C129 P24101 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 129757 T753 C129 P24101 oass.SolrIndexSearcher.<init> Opening Searcher@1f970b01 main
[junit4:junit4] 2> 129758 T752 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f970b01 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 129759 T753 C129 P24101 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index.20130625052021806 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index.20130625052021806;done=true>>]
[junit4:junit4] 2> 129759 T753 C129 P24101 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index.20130625052021806
[junit4:junit4] 2> 129760 T753 C129 P24101 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty4/index.20130625052021806
[junit4:junit4] 2> 129761 T753 C129 P24101 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 129761 T753 C129 P24101 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 129761 T753 C129 P24101 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 129762 T753 C129 P24101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 129763 T753 C129 P24101 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 130009 T768 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 130027 T768 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 130031 T768 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 130034 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 130035 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:24101_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:24101_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24101/ewd/vg"}
[junit4:junit4] 2> 130054 T683 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> 130054 T729 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> 130054 T748 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> 130054 T767 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> 130054 T696 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> 130054 T676 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> 130054 T712 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> 130068 T768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 130091 T768 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 130096 T768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 130097 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 130098 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 130098 T768 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 130099 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 130099 T768 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 130099 T768 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 130100 T768 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty5-1372148417755/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/
[junit4:junit4] 2> 130100 T768 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e2b06f1
[junit4:junit4] 2> 130101 T768 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 130102 T768 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5
[junit4:junit4] 2> 130103 T768 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index/
[junit4:junit4] 2> 130104 T768 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 130105 T768 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index
[junit4:junit4] 2> 130113 T768 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d3ffe7f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 130113 T768 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 130117 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 130117 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 130118 T768 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 130118 T768 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 130119 T768 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 130119 T768 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 130123 T768 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 130124 T768 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 130124 T768 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 130144 T768 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 130154 T768 oass.SolrIndexSearcher.<init> Opening Searcher@29d8c557 main
[junit4:junit4] 2> 130155 T768 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 130155 T768 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 130161 T771 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29d8c557 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 130163 T768 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 130164 T768 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53280/ewd/vg collection:collection1 shard:shard1
[junit4:junit4] 2> 130167 T768 oasc.ZkController.register We are http://127.0.0.1:53280/ewd/vg/collection1/ and leader is http://127.0.0.1:20971/ewd/vg/collection1/
[junit4:junit4] 2> 130168 T768 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53280/ewd/vg
[junit4:junit4] 2> 130168 T768 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 130168 T768 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C131 name=collection1 org.apache.solr.core.SolrCore@7dc53a1d url=http://127.0.0.1:53280/ewd/vg/collection1 node=127.0.0.1:53280_ewd%2Fvg C131_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53280_ewd%2Fvg, base_url=http://127.0.0.1:53280/ewd/vg}
[junit4:junit4] 2> 130168 T772 C131 P53280 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 130169 T768 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 130169 T772 C131 P53280 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 130170 T772 C131 P53280 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 130170 T772 C131 P53280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 130170 T652 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 130171 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 130171 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 130177 T772 C131 P53280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 130195 T688 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:53280_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 130448 T652 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 130451 T652 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:17100
[junit4:junit4] 2> 130451 T652 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 130452 T652 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 130452 T652 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265
[junit4:junit4] 2> 130453 T652 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/solr.xml
[junit4:junit4] 2> 130453 T652 oasc.CoreContainer.<init> New CoreContainer 367113060
[junit4:junit4] 2> 130454 T652 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/'
[junit4:junit4] 2> 130454 T652 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/'
[junit4:junit4] 2> 130590 T652 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 130591 T652 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 130591 T652 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 130592 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 130592 T652 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 130592 T652 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 130593 T652 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 130593 T652 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 130594 T652 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 130594 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 130612 T652 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 130612 T652 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:39616/solr
[junit4:junit4] 2> 130613 T652 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 130614 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 130617 T784 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32f2c7e5 name:ZooKeeperConnection Watcher:127.0.0.1:39616 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 130618 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 130630 T652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 130643 T652 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 130646 T786 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d0e96f4 name:ZooKeeperConnection Watcher:127.0.0.1:39616/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 130646 T652 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 130657 T652 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 131559 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 131560 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53280_ewd%2Fvg_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53280_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53280/ewd/vg"}
[junit4:junit4] 2> 131575 T767 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> 131575 T676 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> 131575 T748 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> 131575 T729 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> 131575 T696 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> 131575 T786 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> 131575 T712 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> 131575 T683 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> 131660 T652 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:17100_ewd%2Fvg
[junit4:junit4] 2> 131662 T652 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:17100_ewd%2Fvg
[junit4:junit4] 2> 131664 T767 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> 131664 T676 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> 131665 T712 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131664 T786 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> 131665 T712 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> 131665 T729 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131665 T696 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131665 T748 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131665 T683 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131666 T748 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> 131666 T696 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> 131666 T676 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131666 T767 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131666 T729 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> 131667 T683 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> 131674 T786 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 131679 T787 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 131679 T787 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 132198 T688 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:53280_ewd%2Fvg_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 132198 T688 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:53280_ewd%252Fvg_collection1&state=recovering&nodeName=127.0.0.1:53280_ewd%252Fvg&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 133079 T677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 133080 T677 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:17100_ewd%2Fvg",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:17100/ewd/vg"}
[junit4:junit4] 2> 133081 T677 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 133081 T677 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 133098 T683 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> 133098 T748 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> 133098 T729 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> 133098 T786 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> 133098 T676 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> 133098 T767 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> 133098 T696 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> 133098 T712 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> 133683 T787 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/collection1
[junit4:junit4] 2> 133683 T787 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 133684 T787 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 133684 T787 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 133686 T787 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/collection1/'
[junit4:junit4] 2> 133687 T787 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/collection1/lib/README' to classloader
[junit4:junit4] 2> 133688 T787 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty6-1372148422265/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 133743 T787 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 133802 T787 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 133804 T787 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 133828 T787 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C132 name=collection1 org.apache.solr.core.SolrCore@7dc53a1d url=http://127.0.0.1:53280/ewd/vg/collection1 node=127.0.0.1:53280_ewd%2Fvg C132_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53280_ewd%2Fvg, base_url=http://127.0.0.1:53280/ewd/vg}
[junit4:junit4] 2> 134200 T772 C132 P53280 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:20971/ewd/vg/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 134200 T772 C132 P53280 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53280/ewd/vg START replicas=[http://127.0.0.1:20971/ewd/vg/collection1/] nUpdates=100
[junit4:junit4] 2> 134201 T772 C132 P53280 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 134201 T772 C132 P53280 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 134201 T772 C132 P53280 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 134201 T772 C132 P53280 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 134201 T772 C132 P53280 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 134202 T772 C132 P53280 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:20971/ewd/vg/collection1/. core=collection1
[junit4:junit4] 2> 134202 T772 C132 P53280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C133 name=collection1 org.apache.solr.core.SolrCore@2660fd4b url=http://127.0.0.1:20971/ewd/vg/collection1 node=127.0.0.1:20971_ewd%2Fvg C133_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:20971_ewd%2Fvg, base_url=http://127.0.0.1:20971/ewd/vg, leader=true}
[junit4:junit4] 2> 134204 T687 C133 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 134216 T690 C133 P20971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 134253 T690 C133 P20971 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1426241c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 134253 T690 C133 P20971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 134256 T690 C133 P20971 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 134256 T690 C133 P20971 oasup.LogUpdateProcessor.finish [collection1] webapp=/ewd/vg path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 40
[junit4:junit4] 2> 134258 T772 C132 P53280 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 134258 T772 C132 P53280 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 134261 T689 C133 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 134262 T772 C132 P53280 oash.SnapPuller.fetchLatestIndex Master's generation: 5
[junit4:junit4] 2> 134262 T772 C132 P53280 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 134262 T772 C132 P53280 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 134267 T689 C133 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=5&version=2} status=0 QTime=2
[junit4:junit4] 2> 134268 T772 C132 P53280 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 134270 T772 C132 P53280 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index.20130625052026341
[junit4:junit4] 2> 134272 T772 C132 P53280 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index.20130625052026341 lockFactory=org.apache.lucene.store.NativeFSLockFactory@643eae; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 134276 T689 C133 P20971 oasc.SolrCore.execute [collection1] webapp=/ewd/vg path=/replication params={file=segments_5&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=5} status=0 QTime=0
[junit4:junit4] 2> 134278 T772 C132 P53280 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 134282 T772 C132 P53280 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 134282 T772 C132 P53280 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 134289 T772 C132 P53280 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d3ffe7f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d3ffe7f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 134289 T772 C132 P53280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 134290 T772 C132 P53280 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 134291 T772 C132 P53280 oass.SolrIndexSearcher.<init> Opening Searcher@6ee9a71f main
[junit4:junit4] 2> 134292 T771 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ee9a71f main{StandardDirectoryReader(segments_5:1:nrt)}
[junit4:junit4] 2> 134293 T772 C132 P53280 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index.20130625052026341 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index.20130625052026341;done=true>>]
[junit4:junit4] 2> 134293 T772 C132 P53280 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index.20130625052026341
[junit4:junit4] 2> 134293 T772 C132 P53280 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty5/index.20130625052026341
[junit4:junit4] 2> 134295 T772 C132 P53280 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 134295 T772 C132 P53280 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 134295 T772 C132 P53280 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 134295 T772 C132 P53280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]
[...truncated too long message...]
:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.create(SolrZkClient.java:284)
[junit4:junit4] 2> at org.apache.solr.cloud.Overseer.createOverseerNode(Overseer.java:731)
[junit4:junit4] 2> at org.apache.solr.cloud.Overseer.getInQueue(Overseer.java:713)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:266)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.rejoinLeaderElection(ElectionContext.java:377)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:170)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[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> 656372 T805 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@6dce7f64
[junit4:junit4] 2> 656373 T805 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=5,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 656374 T805 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 656374 T805 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 656374 T805 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 656378 T805 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 656379 T805 oasc.CachingDirectoryFactory.close Closing NRTCachingDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 656379 T805 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty7/index.20130625052142810 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty7/index.20130625052142810;done=false>>]
[junit4:junit4] 2> 656379 T805 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty7/index.20130625052142810
[junit4:junit4] 2> 656380 T805 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty7 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty7;done=false>>]
[junit4:junit4] 2> 656380 T805 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148393421/jetty7
[junit4:junit4] 2> 656380 T805 oasc.LeaderElector$1.process WARN java.lang.RuntimeException: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer
[junit4:junit4] 2> at org.apache.solr.cloud.Overseer.createOverseerNode(Overseer.java:740)
[junit4:junit4] 2> at org.apache.solr.cloud.Overseer.getInQueue(Overseer.java:713)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:266)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.rejoinLeaderElection(ElectionContext.java:377)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:170)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[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> Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer
[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.create(ZooKeeper.java:783)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$9.execute(SolrZkClient.java:287)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$9.execute(SolrZkClient.java:284)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.create(SolrZkClient.java:284)
[junit4:junit4] 2> at org.apache.solr.cloud.Overseer.createOverseerNode(Overseer.java:731)
[junit4:junit4] 2> ... 13 more
[junit4:junit4] 2>
[junit4:junit4] 2> 656381 T805 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> 656381 T805 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 656382 T805 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> 656382 T805 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 656382 T805 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=MockFixedIntBlock(blockSize=1591), text=PostingsFormat(name=MockRandom), _version_=MockFixedIntBlock(blockSize=1591), rnd_b=Lucene41(blocksize=128), intDefault=MockFixedIntBlock(blockSize=1591), timestamp=MockFixedIntBlock(blockSize=1591), id=Lucene41(blocksize=128), a_t=MockFixedIntBlock(blockSize=1591), range_facet_sl=PostingsFormat(name=MockRandom), range_facet_si=PostingsFormat(name=NestedPulsing), other_tl1=MockFixedIntBlock(blockSize=1591), multiDefault=PostingsFormat(name=NestedPulsing), a_si=PostingsFormat(name=NestedPulsing)}, docValues:{timestamp=DocValuesFormat(name=Disk)}, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=ar_KW, timezone=America/Halifax
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=56033400,total=202768384
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestConfig, SynonymTokenizerTest, OverseerTest, TestStressVersions, SyncSliceTest]
[junit4:junit4] Completed on J0 in 555.17s, 1 test, 1 failure <<< FAILURES!
[...truncated 837 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:393: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 failure, 11 ignored (5 assumptions)
Total time: 105 minutes 31 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure