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/05/31 12:03:02 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4030 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4030/
2 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:38300 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:38300 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([2FC1E187373C5811:AE276F9F4063382D]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:27106/ogmsi/tl/collection1lastClient and got 5 from http://127.0.0.1:28895/ogmsi/tl/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:27106/ogmsi/tl/collection1lastClient and got 5 from http://127.0.0.1:28895/ogmsi/tl/collection1
at __randomizedtesting.SeedInfo.seed([2FC1E187373C5811:AE276F9F4063382D]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9460 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 210272 T411 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /ogmsi/tl
[junit4:junit4] 2> 210276 T411 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1369992701963
[junit4:junit4] 2> 210277 T411 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 210278 T412 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 210379 T411 oasc.ZkTestServer.run start zk server on port:51191
[junit4:junit4] 2> 210380 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 210384 T418 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6be98e3e name:ZooKeeperConnection Watcher:127.0.0.1:51191 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 210384 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 210385 T411 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 210407 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 210410 T420 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74ee46b3 name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 210410 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 210410 T411 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 210422 T411 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 210426 T411 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 210430 T411 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 210434 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 210434 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 210446 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 210447 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 210555 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 210556 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 210560 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 210561 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 210565 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 210566 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 210570 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 210571 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 210575 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 210576 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 210580 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 210581 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 210585 T411 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 210586 T411 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 210859 T411 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 210863 T411 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:36610
[junit4:junit4] 2> 210864 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 210865 T411 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 210865 T411 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277
[junit4:junit4] 2> 210866 T411 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/solr.xml
[junit4:junit4] 2> 210866 T411 oasc.CoreContainer.<init> New CoreContainer 1814440606
[junit4:junit4] 2> 210867 T411 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/'
[junit4:junit4] 2> 210868 T411 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/'
[junit4:junit4] 2> 210996 T411 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 210997 T411 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 210997 T411 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 210998 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 210998 T411 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 210999 T411 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 210999 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 211000 T411 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 211000 T411 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 211001 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 211020 T411 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 211021 T411 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51191/solr
[junit4:junit4] 2> 211021 T411 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 211023 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 211026 T431 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bb6a05d name:ZooKeeperConnection Watcher:127.0.0.1:51191 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 211027 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 211040 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 211050 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 211052 T433 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@da65f1d name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 211052 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 211060 T411 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 211066 T411 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 211071 T411 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 211074 T411 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36610_ogmsi%2Ftl
[junit4:junit4] 2> 211081 T411 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36610_ogmsi%2Ftl
[junit4:junit4] 2> 211086 T411 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 211102 T411 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 211105 T411 oasc.Overseer.start Overseer (id=89783841716371459-127.0.0.1:36610_ogmsi%2Ftl-n_0000000000) starting
[junit4:junit4] 2> 211118 T411 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 211129 T435 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 211130 T411 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 211133 T411 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 211136 T411 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 211140 T434 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 211150 T436 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/collection1
[junit4:junit4] 2> 211150 T436 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 211151 T436 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 211151 T436 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 211154 T436 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/collection1/'
[junit4:junit4] 2> 211155 T436 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/collection1/lib/README' to classloader
[junit4:junit4] 2> 211156 T436 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 211209 T436 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 211270 T436 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 211373 T436 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 211380 T436 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 212007 T436 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 212022 T436 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 212026 T436 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 212050 T436 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 212056 T436 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 212061 T436 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 212062 T436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 212063 T436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 212063 T436 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 212065 T436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 212065 T436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 212065 T436 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 212113 T436 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1369992702277/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/
[junit4:junit4] 2> 212113 T436 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55877de5
[junit4:junit4] 2> 212113 T436 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 212115 T436 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data
[junit4:junit4] 2> 212116 T436 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index/
[junit4:junit4] 2> 212117 T436 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 212118 T436 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index
[junit4:junit4] 2> 212126 T436 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e3eb0d8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 212127 T436 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 212130 T436 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 212130 T436 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 212131 T436 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 212132 T436 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 212132 T436 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 212132 T436 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 212133 T436 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 212133 T436 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 212134 T436 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 212150 T436 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 212159 T436 oass.SolrIndexSearcher.<init> Opening Searcher@249905e4 main
[junit4:junit4] 2> 212161 T436 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 212161 T436 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 212165 T437 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@249905e4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 212167 T436 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 212167 T436 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 212645 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 212646 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:36610_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36610/ogmsi/tl"}
[junit4:junit4] 2> 212647 T434 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 212680 T434 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 212706 T433 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> 213171 T436 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 213171 T436 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36610/ogmsi/tl collection:control_collection shard:shard1
[junit4:junit4] 2> 213184 T436 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 213204 T436 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 213228 T436 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 213232 T436 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 213233 T436 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 213239 T436 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36610/ogmsi/tl/collection1/
[junit4:junit4] 2> 213240 T436 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 213240 T436 oasc.SyncStrategy.syncToMe http://127.0.0.1:36610/ogmsi/tl/collection1/ has no replicas
[junit4:junit4] 2> 213240 T436 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36610/ogmsi/tl/collection1/
[junit4:junit4] 2> 213241 T436 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 214212 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 214262 T433 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> 214283 T436 oasc.ZkController.register We are http://127.0.0.1:36610/ogmsi/tl/collection1/ and leader is http://127.0.0.1:36610/ogmsi/tl/collection1/
[junit4:junit4] 2> 214283 T436 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36610/ogmsi/tl
[junit4:junit4] 2> 214283 T436 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 214284 T436 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 214284 T436 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 214286 T436 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 214288 T411 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 214288 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 214289 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 214304 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 214315 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 214319 T440 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14a1b15 name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 214319 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 214322 T411 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 214328 T411 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 214625 T411 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 214628 T411 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:30366
[junit4:junit4] 2> 214629 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 214630 T411 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 214630 T411 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015
[junit4:junit4] 2> 214631 T411 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/solr.xml
[junit4:junit4] 2> 214631 T411 oasc.CoreContainer.<init> New CoreContainer 1018480479
[junit4:junit4] 2> 214632 T411 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/'
[junit4:junit4] 2> 214632 T411 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/'
[junit4:junit4] 2> 214760 T411 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 214761 T411 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 214761 T411 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 214762 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 214762 T411 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 214763 T411 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 214763 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 214764 T411 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 214764 T411 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 214765 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 214784 T411 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 214784 T411 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51191/solr
[junit4:junit4] 2> 214785 T411 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 214786 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 214818 T451 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a2c2f09 name:ZooKeeperConnection Watcher:127.0.0.1:51191 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 214818 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 214822 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 214836 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 214839 T453 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10147024 name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 214839 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 214851 T411 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 215776 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 215777 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:36610_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36610/ogmsi/tl"}
[junit4:junit4] 2> 215793 T453 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> 215793 T433 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> 215793 T440 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> 215856 T411 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:30366_ogmsi%2Ftl
[junit4:junit4] 2> 215858 T411 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:30366_ogmsi%2Ftl
[junit4:junit4] 2> 215862 T440 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 215862 T433 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 215862 T440 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> 215862 T453 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 215863 T433 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> 215863 T453 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> 215882 T454 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/collection1
[junit4:junit4] 2> 215882 T454 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 215883 T454 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 215883 T454 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 215885 T454 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/collection1/'
[junit4:junit4] 2> 215887 T454 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 215887 T454 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/collection1/lib/README' to classloader
[junit4:junit4] 2> 215940 T454 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 216012 T454 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 216115 T454 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 216122 T454 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 216761 T454 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 216788 T454 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 216793 T454 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 216817 T454 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 216822 T454 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 216828 T454 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 216829 T454 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 216830 T454 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 216830 T454 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 216831 T454 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 216832 T454 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 216832 T454 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 216832 T454 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1369992706015/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/
[junit4:junit4] 2> 216833 T454 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55877de5
[junit4:junit4] 2> 216833 T454 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 216835 T454 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1
[junit4:junit4] 2> 216836 T454 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index/
[junit4:junit4] 2> 216837 T454 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 216837 T454 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index
[junit4:junit4] 2> 216845 T454 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 216846 T454 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 216849 T454 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 216850 T454 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 216850 T454 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 216851 T454 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 216852 T454 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 216852 T454 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 216852 T454 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 216853 T454 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 216854 T454 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 216872 T454 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 216882 T454 oass.SolrIndexSearcher.<init> Opening Searcher@138bb487 main
[junit4:junit4] 2> 216884 T454 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 216884 T454 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 216888 T455 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@138bb487 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 216891 T454 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 216891 T454 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 217301 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 217302 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:30366_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:30366/ogmsi/tl"}
[junit4:junit4] 2> 217302 T434 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 217302 T434 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 217315 T453 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> 217315 T433 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> 217315 T440 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> 217894 T454 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 217894 T454 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:30366/ogmsi/tl collection:collection1 shard:shard1
[junit4:junit4] 2> 217895 T454 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 217914 T454 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 217925 T454 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 217926 T454 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 217926 T454 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 217926 T454 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 217927 T454 oasc.SyncStrategy.syncToMe http://127.0.0.1:30366/ogmsi/tl/collection1/ has no replicas
[junit4:junit4] 2> 217927 T454 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 217927 T454 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 218822 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 218841 T453 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> 218841 T433 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> 218841 T440 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> 218856 T454 oasc.ZkController.register We are http://127.0.0.1:30366/ogmsi/tl/collection1/ and leader is http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 218856 T454 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:30366/ogmsi/tl
[junit4:junit4] 2> 218856 T454 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 218856 T454 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 218857 T454 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 218860 T454 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 218861 T411 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 218862 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 218862 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 219164 T411 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 219168 T411 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12293
[junit4:junit4] 2> 219168 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 219169 T411 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 219169 T411 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566
[junit4:junit4] 2> 219170 T411 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/solr.xml
[junit4:junit4] 2> 219170 T411 oasc.CoreContainer.<init> New CoreContainer 1275831735
[junit4:junit4] 2> 219171 T411 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/'
[junit4:junit4] 2> 219172 T411 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/'
[junit4:junit4] 2> 219304 T411 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 219305 T411 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 219306 T411 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 219306 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 219307 T411 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 219307 T411 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 219308 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 219308 T411 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 219309 T411 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 219309 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 219326 T411 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 219327 T411 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51191/solr
[junit4:junit4] 2> 219328 T411 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 219329 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 219332 T467 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@301e026a name:ZooKeeperConnection Watcher:127.0.0.1:51191 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 219332 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 219335 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 219347 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 219350 T469 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11364b81 name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 219350 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 219362 T411 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 220356 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 220358 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:30366_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:30366/ogmsi/tl"}
[junit4:junit4] 2> 220385 T411 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12293_ogmsi%2Ftl
[junit4:junit4] 2> 220387 T411 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12293_ogmsi%2Ftl
[junit4:junit4] 2> 220401 T453 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 220401 T469 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 220401 T453 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> 220401 T440 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 220401 T469 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> 220402 T440 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> 220408 T453 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> 220409 T440 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> 220410 T433 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 220410 T433 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> 220412 T433 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> 220415 T470 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/collection1
[junit4:junit4] 2> 220415 T470 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 220416 T470 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 220416 T470 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 220418 T470 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/collection1/'
[junit4:junit4] 2> 220420 T470 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/collection1/lib/README' to classloader
[junit4:junit4] 2> 220420 T470 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 220472 T470 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 220533 T470 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 220635 T470 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 220642 T470 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 221277 T470 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 221292 T470 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 221296 T470 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 221320 T470 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 221325 T470 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 221331 T470 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 221332 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 221333 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 221333 T470 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 221335 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 221335 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 221335 T470 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 221336 T470 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1369992710566/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/
[junit4:junit4] 2> 221336 T470 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55877de5
[junit4:junit4] 2> 221337 T470 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 221338 T470 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2
[junit4:junit4] 2> 221339 T470 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index/
[junit4:junit4] 2> 221340 T470 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 221341 T470 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index
[junit4:junit4] 2> 221358 T470 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 221359 T470 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 221362 T470 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 221363 T470 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 221364 T470 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 221364 T470 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 221365 T470 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 221365 T470 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 221366 T470 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 221366 T470 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 221367 T470 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 221386 T470 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 221396 T470 oass.SolrIndexSearcher.<init> Opening Searcher@439a59e5 main
[junit4:junit4] 2> 221398 T470 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 221398 T470 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 221403 T471 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@439a59e5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 221406 T470 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 221406 T470 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 221913 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 221915 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12293_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12293/ogmsi/tl"}
[junit4:junit4] 2> 221915 T434 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 221915 T434 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 221928 T469 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> 221929 T453 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> 221929 T440 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> 221929 T433 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> 222413 T470 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 222413 T470 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12293/ogmsi/tl collection:collection1 shard:shard1
[junit4:junit4] 2> 222417 T470 oasc.ZkController.register We are http://127.0.0.1:12293/ogmsi/tl/collection1/ and leader is http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 222418 T470 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12293/ogmsi/tl
[junit4:junit4] 2> 222418 T470 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 222418 T470 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C268 name=collection1 org.apache.solr.core.SolrCore@62df7f31 url=http://127.0.0.1:12293/ogmsi/tl/collection1 node=127.0.0.1:12293_ogmsi%2Ftl C268_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:12293_ogmsi%2Ftl, base_url=http://127.0.0.1:12293/ogmsi/tl}
[junit4:junit4] 2> 222426 T472 C268 P12293 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 222427 T470 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 222427 T472 C268 P12293 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 222428 T472 C268 P12293 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 222428 T472 C268 P12293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 222429 T411 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 222429 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 222430 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 222430 T472 C268 P12293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 222471 T443 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 222737 T411 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 222740 T411 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:27106
[junit4:junit4] 2> 222742 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 222742 T411 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 222743 T411 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137
[junit4:junit4] 2> 222743 T411 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/solr.xml
[junit4:junit4] 2> 222744 T411 oasc.CoreContainer.<init> New CoreContainer 1252991878
[junit4:junit4] 2> 222744 T411 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/'
[junit4:junit4] 2> 222745 T411 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/'
[junit4:junit4] 2> 222882 T411 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 222883 T411 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 222883 T411 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 222884 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 222884 T411 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 222885 T411 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 222885 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 222886 T411 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 222886 T411 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 222887 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 222907 T411 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 222908 T411 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51191/solr
[junit4:junit4] 2> 222909 T411 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 222910 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 222913 T484 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50b93e10 name:ZooKeeperConnection Watcher:127.0.0.1:51191 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 222914 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 222924 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 222943 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 222946 T486 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d6e44ca name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 222946 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 222953 T411 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 223435 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 223437 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12293_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12293/ogmsi/tl"}
[junit4:junit4] 2> 223451 T453 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> 223451 T469 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> 223451 T486 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> 223451 T433 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> 223451 T440 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> 223474 T443 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 223474 T443 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:12293_ogmsi%252Ftl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1012
[junit4:junit4] 2> 223959 T411 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:27106_ogmsi%2Ftl
[junit4:junit4] 2> 223967 T411 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:27106_ogmsi%2Ftl
[junit4:junit4] 2> 223972 T440 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 223972 T453 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 223973 T486 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 223973 T433 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 223972 T440 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> 223972 T469 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 223973 T433 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> 223973 T486 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> 223973 T453 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> 223974 T469 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> 223995 T487 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/collection1
[junit4:junit4] 2> 223996 T487 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 223996 T487 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 223997 T487 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 223999 T487 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/collection1/'
[junit4:junit4] 2> 224000 T487 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 224001 T487 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/collection1/lib/README' to classloader
[junit4:junit4] 2> 224053 T487 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 224113 T487 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 224216 T487 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 224223 T487 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 224847 T487 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 224861 T487 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 224865 T487 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 224889 T487 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 224894 T487 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 224899 T487 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 224901 T487 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 224902 T487 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 224902 T487 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 224903 T487 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 224904 T487 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 224904 T487 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 224904 T487 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1369992714137/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/
[junit4:junit4] 2> 224905 T487 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55877de5
[junit4:junit4] 2> 224905 T487 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 224906 T487 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3
[junit4:junit4] 2> 224907 T487 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index/
[junit4:junit4] 2> 224908 T487 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 224909 T487 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index
[junit4:junit4] 2> 224916 T487 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 224916 T487 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 224920 T487 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 224920 T487 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 224921 T487 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 224922 T487 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 224922 T487 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 224923 T487 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 224923 T487 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 224924 T487 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 224924 T487 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 224940 T487 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 224950 T487 oass.SolrIndexSearcher.<init> Opening Searcher@2fa9dd0e main
[junit4:junit4] 2> 224951 T487 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 224952 T487 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 224956 T488 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2fa9dd0e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 224959 T487 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 224959 T487 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C269 name=collection1 org.apache.solr.core.SolrCore@62df7f31 url=http://127.0.0.1:12293/ogmsi/tl/collection1 node=127.0.0.1:12293_ogmsi%2Ftl C269_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:12293_ogmsi%2Ftl, base_url=http://127.0.0.1:12293/ogmsi/tl}
[junit4:junit4] 2> 225476 T472 C269 P12293 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:30366/ogmsi/tl/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 225488 T472 C269 P12293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 225515 T472 C269 P12293 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12293/ogmsi/tl START replicas=[http://127.0.0.1:30366/ogmsi/tl/collection1/] nUpdates=100
[junit4:junit4] 2> 225516 T472 C269 P12293 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 225516 T472 C269 P12293 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 225517 T472 C269 P12293 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 225517 T472 C269 P12293 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 225517 T472 C269 P12293 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 225517 T472 C269 P12293 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:30366/ogmsi/tl/collection1/. core=collection1
[junit4:junit4] 2> 225518 T472 C269 P12293 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C270 name=collection1 org.apache.solr.core.SolrCore@1e6a3d63 url=http://127.0.0.1:30366/ogmsi/tl/collection1 node=127.0.0.1:30366_ogmsi%2Ftl C270_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:30366_ogmsi%2Ftl, base_url=http://127.0.0.1:30366/ogmsi/tl, leader=true}
[junit4:junit4] 2> 225526 T444 C270 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 225553 T445 C270 P30366 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 225558 T445 C270 P30366 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 225559 T445 C270 P30366 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 225563 T445 C270 P30366 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 225564 T445 C270 P30366 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 225566 T445 C270 P30366 oass.SolrIndexSearcher.<init> Opening Searcher@5dcf4a6 realtime
[junit4:junit4] 2> 225566 T445 C270 P30366 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 225567 T445 C270 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 36
[junit4:junit4] 2> 225568 T472 C269 P12293 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 225568 T472 C269 P12293 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 225599 T472 C269 P12293 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 225602 T446 C270 P30366 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 225603 T446 C270 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 225604 T472 C269 P12293 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 225604 T472 C269 P12293 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 225604 T472 C269 P12293 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 225609 T446 C270 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2
[junit4:junit4] 2> 225610 T472 C269 P12293 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 225612 T472 C269 P12293 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index.20130531043157296
[junit4:junit4] 2> 225613 T472 C269 P12293 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index.20130531043157296 lockFactory=org.apache.lucene.store.NativeFSLockFactory@352b747c; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 225630 T446 C270 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=6
[junit4:junit4] 2> 225648 T472 C269 P12293 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 225652 T472 C269 P12293 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 225652 T472 C269 P12293 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 225664 T472 C269 P12293 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 225665 T472 C269 P12293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 225666 T472 C269 P12293 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 225667 T472 C269 P12293 oass.SolrIndexSearcher.<init> Opening Searcher@58ef86f0 main
[junit4:junit4] 2> 225668 T471 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@58ef86f0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 225669 T472 C269 P12293 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index.20130531043157296 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index.20130531043157296;done=true>>]
[junit4:junit4] 2> 225669 T472 C269 P12293 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index.20130531043157296
[junit4:junit4] 2> 225670 T472 C269 P12293 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index.20130531043157296
[junit4:junit4] 2> 225680 T472 C269 P12293 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 225680 T472 C269 P12293 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 225680 T472 C269 P12293 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 225681 T472 C269 P12293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 225683 T472 C269 P12293 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 226460 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 226461 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:27106_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:27106/ogmsi/tl"}
[junit4:junit4] 2> 226462 T434 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 226462 T434 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 226492 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12293_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12293/ogmsi/tl"}
[junit4:junit4] 2> 226502 T453 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> 226502 T486 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> 226502 T469 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> 226502 T433 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> 226502 T440 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> 226964 T487 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 226964 T487 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:27106/ogmsi/tl collection:collection1 shard:shard1
[junit4:junit4] 2> 226969 T487 oasc.ZkController.register We are http://127.0.0.1:27106/ogmsi/tl/collection1/ and leader is http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 226970 T487 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:27106/ogmsi/tl
[junit4:junit4] 2> 226970 T487 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 226970 T487 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C271 name=collection1 org.apache.solr.core.SolrCore@4f8a312c url=http://127.0.0.1:27106/ogmsi/tl/collection1 node=127.0.0.1:27106_ogmsi%2Ftl C271_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:27106_ogmsi%2Ftl, base_url=http://127.0.0.1:27106/ogmsi/tl}
[junit4:junit4] 2> 226971 T491 C271 P27106 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 226972 T487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 226972 T491 C271 P27106 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 226973 T491 C271 P27106 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 226973 T491 C271 P27106 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 226974 T411 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 226974 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 226975 T491 C271 P27106 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 226975 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 227003 T447 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 227270 T411 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 227273 T411 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:28895
[junit4:junit4] 2> 227274 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 227275 T411 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 227275 T411 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686
[junit4:junit4] 2> 227276 T411 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/solr.xml
[junit4:junit4] 2> 227276 T411 oasc.CoreContainer.<init> New CoreContainer 328532789
[junit4:junit4] 2> 227277 T411 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/'
[junit4:junit4] 2> 227278 T411 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/'
[junit4:junit4] 2> 227405 T411 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 227406 T411 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 227407 T411 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 227407 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 227408 T411 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 227408 T411 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 227409 T411 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 227409 T411 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 227410 T411 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 227410 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 227428 T411 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 227428 T411 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51191/solr
[junit4:junit4] 2> 227429 T411 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 227430 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 227434 T503 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cd72139 name:ZooKeeperConnection Watcher:127.0.0.1:51191 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 227434 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 227446 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 227459 T411 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 227461 T505 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@362642ed name:ZooKeeperConnection Watcher:127.0.0.1:51191/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 227461 T411 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 227472 T411 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 228018 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 228020 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:27106_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:27106/ogmsi/tl"}
[junit4:junit4] 2> 228026 T453 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> 228026 T486 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> 228026 T469 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> 228026 T433 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> 228026 T440 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> 228026 T505 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> 228478 T411 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:28895_ogmsi%2Ftl
[junit4:junit4] 2> 228480 T411 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:28895_ogmsi%2Ftl
[junit4:junit4] 2> 228484 T505 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> 228484 T453 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 228484 T433 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 228485 T486 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 228485 T433 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> 228485 T469 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 228484 T453 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> 228484 T440 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 228485 T469 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> 228485 T486 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> 228486 T440 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> 228487 T505 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 228495 T506 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/collection1
[junit4:junit4] 2> 228495 T506 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 228496 T506 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 228496 T506 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 228498 T506 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/collection1/'
[junit4:junit4] 2> 228500 T506 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/collection1/lib/README' to classloader
[junit4:junit4] 2> 228500 T506 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 228554 T506 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 228633 T506 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 228735 T506 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 228743 T506 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 229259 T447 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 229259 T447 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:27106_ogmsi%252Ftl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2257
[junit4:junit4] 2> 229287 T506 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 229298 T506 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 229300 T506 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 229320 T506 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 229324 T506 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 229328 T506 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 229330 T506 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 229330 T506 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 229330 T506 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 229331 T506 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 229332 T506 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 229332 T506 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 229332 T506 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1369992718686/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/
[junit4:junit4] 2> 229333 T506 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@55877de5
[junit4:junit4] 2> 229333 T506 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 229334 T506 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4
[junit4:junit4] 2> 229334 T506 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index/
[junit4:junit4] 2> 229335 T506 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 229336 T506 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index
[junit4:junit4] 2> 229341 T506 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 229342 T506 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 229356 T506 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 229356 T506 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 229357 T506 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 229357 T506 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 229358 T506 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 229358 T506 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 229358 T506 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 229359 T506 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 229359 T506 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 229372 T506 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 229381 T506 oass.SolrIndexSearcher.<init> Opening Searcher@353ad96 main
[junit4:junit4] 2> 229382 T506 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 229382 T506 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 229386 T507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@353ad96 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 229388 T506 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 229388 T506 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 229534 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 229535 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:28895_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28895/ogmsi/tl"}
[junit4:junit4] 2> 229535 T434 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 229536 T434 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 229547 T453 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> 229547 T469 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> 229547 T505 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> 229547 T486 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> 229547 T433 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> 229547 T440 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> 230391 T506 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 230391 T506 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:28895/ogmsi/tl collection:collection1 shard:shard1
[junit4:junit4] 2> 230424 T506 oasc.ZkController.register We are http://127.0.0.1:28895/ogmsi/tl/collection1/ and leader is http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 230424 T506 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:28895/ogmsi/tl
[junit4:junit4] 2> 230424 T506 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 230425 T506 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C272 name=collection1 org.apache.solr.core.SolrCore@31c12b61 url=http://127.0.0.1:28895/ogmsi/tl/collection1 node=127.0.0.1:28895_ogmsi%2Ftl C272_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:28895_ogmsi%2Ftl, base_url=http://127.0.0.1:28895/ogmsi/tl}
[junit4:junit4] 2> 230425 T508 C272 P28895 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 230426 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 230426 T506 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 230426 T508 C272 P28895 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 230427 T508 C272 P28895 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 230428 T411 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 230428 T411 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 230429 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 230433 T508 C272 P28895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 230454 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 230455 T448 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 230456 T411 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 230457 T411 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 230458 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 231053 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 231054 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:28895_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28895/ogmsi/tl"}
[junit4:junit4] 2> 231102 T453 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> 231102 T486 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> 231102 T440 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> 231102 T469 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> 231102 T505 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> 231102 T433 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> ASYNC NEW_CORE C273 name=collection1 org.apache.solr.core.SolrCore@4f8a312c url=http://127.0.0.1:27106/ogmsi/tl/collection1 node=127.0.0.1:27106_ogmsi%2Ftl C273_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:27106_ogmsi%2Ftl, base_url=http://127.0.0.1:27106/ogmsi/tl}
[junit4:junit4] 2> 231261 T491 C273 P27106 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:30366/ogmsi/tl/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 231261 T491 C273 P27106 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:27106/ogmsi/tl START replicas=[http://127.0.0.1:30366/ogmsi/tl/collection1/] nUpdates=100
[junit4:junit4] 2> 231262 T491 C273 P27106 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 231262 T491 C273 P27106 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 231262 T491 C273 P27106 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 231263 T491 C273 P27106 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 231263 T491 C273 P27106 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 231263 T491 C273 P27106 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:30366/ogmsi/tl/collection1/. core=collection1
[junit4:junit4] 2> 231263 T491 C273 P27106 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C274 name=collection1 org.apache.solr.core.SolrCore@1e6a3d63 url=http://127.0.0.1:30366/ogmsi/tl/collection1 node=127.0.0.1:30366_ogmsi%2Ftl C274_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:30366_ogmsi%2Ftl, base_url=http://127.0.0.1:30366/ogmsi/tl, leader=true}
[junit4:junit4] 2> 231265 T444 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 231274 T449 C274 P30366 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 231277 T449 C274 P30366 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 231278 T449 C274 P30366 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 231279 T449 C274 P30366 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 231279 T449 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 231280 T491 C273 P27106 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 231280 T491 C273 P27106 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 231283 T446 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 231284 T491 C273 P27106 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 231285 T491 C273 P27106 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 231285 T491 C273 P27106 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 231288 T446 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 231289 T491 C273 P27106 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 231290 T491 C273 P27106 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index.20130531043202975
[junit4:junit4] 2> 231291 T491 C273 P27106 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index.20130531043202975 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71c05518; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 231294 T446 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 231296 T491 C273 P27106 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 231298 T491 C273 P27106 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 231298 T491 C273 P27106 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 231302 T491 C273 P27106 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 231302 T491 C273 P27106 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 231302 T491 C273 P27106 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 231303 T491 C273 P27106 oass.SolrIndexSearcher.<init> Opening Searcher@26b1ba1a main
[junit4:junit4] 2> 231304 T488 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@26b1ba1a main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 231304 T491 C273 P27106 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index.20130531043202975 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index.20130531043202975;done=true>>]
[junit4:junit4] 2> 231305 T491 C273 P27106 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index.20130531043202975
[junit4:junit4] 2> 231305 T491 C273 P27106 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index.20130531043202975
[junit4:junit4] 2> 231306 T491 C273 P27106 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 231306 T491 C273 P27106 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 231306 T491 C273 P27106 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 231306 T491 C273 P27106 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 231308 T491 C273 P27106 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 231457 T448 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 231457 T448 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:28895_ogmsi%252Ftl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 231460 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 232463 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 232608 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 232608 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:27106_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:27106/ogmsi/tl"}
[junit4:junit4] 2> 232629 T440 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> 232629 T469 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> 232629 T505 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> 232629 T486 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> 232629 T453 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> 232629 T433 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> C272_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:28895_ogmsi%2Ftl, base_url=http://127.0.0.1:28895/ogmsi/tl}
[junit4:junit4] 2> 233459 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:30366/ogmsi/tl/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 233459 T508 C272 P28895 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:28895/ogmsi/tl START replicas=[http://127.0.0.1:30366/ogmsi/tl/collection1/] nUpdates=100
[junit4:junit4] 2> 233460 T508 C272 P28895 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 233460 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 233460 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 233460 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 233461 T508 C272 P28895 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 233461 T508 C272 P28895 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:30366/ogmsi/tl/collection1/. core=collection1
[junit4:junit4] 2> 233461 T508 C272 P28895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 233463 T444 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 233465 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 233474 T443 C274 P30366 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 233479 T443 C274 P30366 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 233480 T443 C274 P30366 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 233481 T443 C274 P30366 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 233482 T443 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl 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> 233483 T508 C272 P28895 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 233483 T508 C272 P28895 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 233485 T446 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 233486 T508 C272 P28895 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 233486 T508 C272 P28895 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 233486 T508 C272 P28895 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 233490 T446 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 233491 T508 C272 P28895 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 233493 T508 C272 P28895 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index.20130531043205178
[junit4:junit4] 2> 233494 T508 C272 P28895 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index.20130531043205178 lockFactory=org.apache.lucene.store.NativeFSLockFactory@432b55e; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 233497 T446 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 233499 T508 C272 P28895 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 233501 T508 C272 P28895 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 233501 T508 C272 P28895 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 233505 T508 C272 P28895 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 233506 T508 C272 P28895 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 233506 T508 C272 P28895 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 233507 T508 C272 P28895 oass.SolrIndexSearcher.<init> Opening Searcher@12a0dd84 main
[junit4:junit4] 2> 233508 T507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12a0dd84 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 233508 T508 C272 P28895 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index.20130531043205178 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index.20130531043205178;done=true>>]
[junit4:junit4] 2> 233509 T508 C272 P28895 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index.20130531043205178
[junit4:junit4] 2> 233509 T508 C272 P28895 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index.20130531043205178
[junit4:junit4] 2> 233510 T508 C272 P28895 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 233510 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 233510 T508 C272 P28895 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 233510 T508 C272 P28895 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 233512 T508 C272 P28895 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 234136 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 234137 T434 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:28895_ogmsi%2Ftl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28895/ogmsi/tl"}
[junit4:junit4] 2> 234204 T453 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> 234204 T486 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> 234204 T469 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> 234204 T505 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> 234204 T433 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> 234204 T440 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> 234469 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 234470 T411 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C275 name=collection1 org.apache.solr.core.SolrCore@67f821aa url=http://127.0.0.1:36610/ogmsi/tl/collection1 node=127.0.0.1:36610_ogmsi%2Ftl C275_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:36610_ogmsi%2Ftl, base_url=http://127.0.0.1:36610/ogmsi/tl, leader=true}
[junit4:junit4] 2> 234485 T423 C275 P36610 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 234491 T423 C275 P36610 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e3eb0d8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 234492 T423 C275 P36610 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 234502 T423 C275 P36610 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e3eb0d8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e3eb0d8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 234502 T423 C275 P36610 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 234505 T423 C275 P36610 oass.SolrIndexSearcher.<init> Opening Searcher@6786c507 main
[junit4:junit4] 2> 234505 T423 C275 P36610 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 234506 T437 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6786c507 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 234507 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 234522 T445 C274 P30366 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 234527 T445 C274 P30366 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 234528 T445 C274 P30366 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 234530 T445 C274 P30366 oass.SolrIndexSearcher.<init> Opening Searcher@1de6e9d6 main
[junit4:junit4] 2> 234530 T445 C274 P30366 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 234531 T455 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1de6e9d6 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 234552 T445 C274 P30366 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:12293/ogmsi/tl/collection1/, StdNode: http://127.0.0.1:27106/ogmsi/tl/collection1/, StdNode: http://127.0.0.1:28895/ogmsi/tl/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C273_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:27106_ogmsi%2Ftl, base_url=http://127.0.0.1:27106/ogmsi/tl}
[junit4:junit4] 2> 234587 T476 C273 P27106 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C276 name=collection1 org.apache.solr.core.SolrCore@62df7f31 url=http://127.0.0.1:12293/ogmsi/tl/collection1 node=127.0.0.1:12293_ogmsi%2Ftl C276_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:12293_ogmsi%2Ftl, base_url=http://127.0.0.1:12293/ogmsi/tl}
[junit4:junit4] 2> 234587 T459 C276 P12293 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C272_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:28895_ogmsi%2Ftl, base_url=http://127.0.0.1:28895/ogmsi/tl}
[junit4:junit4] 2> 234587 T495 C272 P28895 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 234603 T476 C273 P27106 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 234604 T459 C276 P12293 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 234604 T495 C272 P28895 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 234605 T459 C276 P12293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 234604 T476 C273 P27106 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 234606 T495 C272 P28895 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 234609 T459 C276 P12293 oass.SolrIndexSearcher.<init> Opening Searcher@49812388 main
[junit4:junit4] 2> 234609 T476 C273 P27106 oass.SolrIndexSearcher.<init> Opening Searcher@31fa6d39 main
[junit4:junit4] 2> 234609 T495 C272 P28895 oass.SolrIndexSearcher.<init> Opening Searcher@2db8b002 main
[junit4:junit4] 2> 234609 T459 C276 P12293 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 234610 T471 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@49812388 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 234610 T495 C272 P28895 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 234610 T476 C273 P27106 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 234612 T507 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceAlreadyExistsException: solr/collection1:type=fieldValueCache,id=org.apache.solr.search.FastLRUCache
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:303)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1791)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:132)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1668)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 234612 T459 C276 P12293 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 234611 T488 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@31fa6d39 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 234613 T507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2db8b002 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 234614 T476 C273 P27106 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 27
[junit4:junit4] 2> 234614 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 27
[junit4:junit4] 2> 234615 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 93
[junit4:junit4] 2> 234617 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 234622 T447 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 234626 T460 C276 P12293 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 234630 T477 C273 P27106 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 234633 T496 C272 P28895 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 236653 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436541495101358080)} 0 15
[junit4:junit4] 2> 236673 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={update.distrib=FROMLEADER&_version_=-1436541495114989568&update.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436541495114989568)} 0 2
[junit4:junit4] 2> 236673 T476 C273 P27106 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={update.distrib=FROMLEADER&_version_=-1436541495114989568&update.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436541495114989568)} 0 2
[junit4:junit4] 2> 236673 T459 C276 P12293 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={update.distrib=FROMLEADER&_version_=-1436541495114989568&update.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436541495114989568)} 0 2
[junit4:junit4] 2> 236675 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436541495114989568)} 0 19
[junit4:junit4] 2> 236683 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {add=[0 (1436541495138058240)]} 0 5
[junit4:junit4] 2> 236710 T459 C276 P12293 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436541495146446848)]} 0 4
[junit4:junit4] 2> 236710 T476 C273 P27106 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436541495146446848)]} 0 4
[junit4:junit4] 2> 236710 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436541495146446848)]} 0 4
[junit4:junit4] 2> 236712 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {add=[0 (1436541495146446848)]} 0 26
[junit4:junit4] 2> 236718 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {add=[1 (1436541495177904128)]} 0 2
[junit4:junit4] 2> 236727 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436541495183147008)]} 0 2
[junit4:junit4] 2> 236727 T459 C276 P12293 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436541495183147008)]} 0 2
[junit4:junit4] 2> 236727 T476 C273 P27106 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436541495183147008)]} 0 2
[junit4:junit4] 2> 236729 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {add=[1 (1436541495183147008)]} 0 8
[junit4:junit4] 2> 236734 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {add=[2 (1436541495194681344)]} 0 2
[junit4:junit4] 2> 236738 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:12293/ogmsi/tl/collection1/]
[junit4:junit4] 2> 236738 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:12293/ogmsi/tl/collection1/ against:[http://127.0.0.1:12293/ogmsi/tl/collection1/] result:true
[junit4:junit4] 2> 236739 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:27106/ogmsi/tl/collection1/ against:[http://127.0.0.1:12293/ogmsi/tl/collection1/] result:false
[junit4:junit4] 2> 236739 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:28895/ogmsi/tl/collection1/ against:[http://127.0.0.1:12293/ogmsi/tl/collection1/] result:false
[junit4:junit4] 2> 236745 T476 C273 P27106 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12293/ogmsi/tl/collection1/&wt=javabin&version=2} {add=[2 (1436541495200972800)]} 0 2
[junit4:junit4] 2> 236745 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12293/ogmsi/tl/collection1/&wt=javabin&version=2} {add=[2 (1436541495200972800)]} 0 2
[junit4:junit4] 2> 236746 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={test.distrib.skip.servers=http://127.0.0.1:12293/ogmsi/tl/collection1/&wt=javabin&version=2} {add=[2 (1436541495200972800)]} 0 9
[junit4:junit4] 2> 236751 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={wt=javabin&version=2} {add=[3 (1436541495212507136)]} 0 2
[junit4:junit4] 2> 236756 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:12293/ogmsi/tl/collection1/, http://127.0.0.1:27106/ogmsi/tl/collection1/]
[junit4:junit4] 2> 236756 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:12293/ogmsi/tl/collection1/ against:[http://127.0.0.1:12293/ogmsi/tl/collection1/, http://127.0.0.1:27106/ogmsi/tl/collection1/] result:true
[junit4:junit4] 2> 236757 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:27106/ogmsi/tl/collection1/ against:[http://127.0.0.1:12293/ogmsi/tl/collection1/, http://127.0.0.1:27106/ogmsi/tl/collection1/] result:true
[junit4:junit4] 2> 236757 T445 C274 P30366 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:28895/ogmsi/tl/collection1/ against:[http://127.0.0.1:12293/ogmsi/tl/collection1/, http://127.0.0.1:27106/ogmsi/tl/collection1/] result:false
[junit4:junit4] 2> 236763 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={distrib.from=http://127.0.0.1:30366/ogmsi/tl/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12293/ogmsi/tl/collection1/&wt=javabin&version=2} {add=[3 (1436541495220895744)]} 0 2
[junit4:junit4] 2> 236764 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={test.distrib.skip.servers=http://127.0.0.1:12293/ogmsi/tl/collection1/&test.distrib.skip.servers=http://127.0.0.1:27106/ogmsi/tl/collection1/&wt=javabin&version=2} {add=[3 (1436541495220895744)]} 0 9
[junit4:junit4] 2> 236767 T423 C275 P36610 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 236861 T423 C275 P36610 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e3eb0d8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e3eb0d8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 236862 T423 C275 P36610 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 236880 T423 C275 P36610 oass.SolrIndexSearcher.<init> Opening Searcher@7e416dcc main
[junit4:junit4] 2> 236881 T423 C275 P36610 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 236881 T437 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e416dcc main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):C4)}
[junit4:junit4] 2> 236882 T423 C275 P36610 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 115
[junit4:junit4] 2> 236887 T445 C274 P30366 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 237025 T445 C274 P30366 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12b56813; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 237026 T445 C274 P30366 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 237043 T445 C274 P30366 oass.SolrIndexSearcher.<init> Opening Searcher@3b362c2 main
[junit4:junit4] 2> 237044 T445 C274 P30366 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 237044 T455 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3b362c2 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):C4)}
[junit4:junit4] 2> 237045 T445 C274 P30366 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:12293/ogmsi/tl/collection1/, StdNode: http://127.0.0.1:27106/ogmsi/tl/collection1/, StdNode: http://127.0.0.1:28895/ogmsi/tl/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 237049 T459 C276 P12293 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 237049 T495 C272 P28895 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 237049 T476 C273 P27106 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 237203 T459 C276 P12293 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d854b15; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 237203 T495 C272 P28895 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6164799f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 237203 T459 C276 P12293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 237204 T495 C272 P28895 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 237206 T476 C273 P27106 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1369992701963/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5afde945; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 237207 T476 C273 P27106 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 237219 T495 C272 P28895 oass.SolrIndexSearcher.<init> Opening Searcher@6e0092d1 main
[junit4:junit4] 2> 237219 T459 C276 P12293 oass.SolrIndexSearcher.<init> Opening Searcher@67a70fc2 main
[junit4:junit4] 2> 237220 T495 C272 P28895 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 237220 T459 C276 P12293 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 237220 T471 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:299)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1791)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:132)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1668)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 237221 T507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e0092d1 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):C4)}
[junit4:junit4] 2> 237221 T471 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@67a70fc2 main{StandardDirectoryReader(segments_4:3:nrt _0(5.0):C2)}
[junit4:junit4] 2> 237222 T495 C272 P28895 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 173
[junit4:junit4] 2> 237222 T459 C276 P12293 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 173
[junit4:junit4] 2> 237226 T476 C273 P27106 oass.SolrIndexSearcher.<init> Opening Searcher@70a8e788 main
[junit4:junit4] 2> 237227 T476 C273 P27106 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 237227 T488 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@70a8e788 main{StandardDirectoryReader(segments_5:3:nrt _0(5.0):C3)}
[junit4:junit4] 2> 237228 T476 C273 P27106 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 179
[junit4:junit4] 2> 237229 T445 C274 P30366 oasup.LogUpdateProcessor.finish [collection1] webapp=/ogmsi/tl path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 342
[junit4:junit4] 2> 237229 T411 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 237230 T411 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 237231 T411 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 237235 T447 C274 P30366 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 237239 T460 C276 P12293 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=1
[junit4:junit4] 2> 237242 T477 C273 P27106 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=0
[junit4:junit4] 2> 237246 T496 C272 P28895 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 237251 T411 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 237270 T478 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 237271 T478 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 237282 T449 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 237282 T449 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:30366/ogmsi/tl/collection1/
[junit4:junit4] 2> 237282 T449 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:30366/ogmsi/tl START replicas=[http://127.0.0.1:12293/ogmsi/tl/collection1/, http://127.0.0.1:27106/ogmsi/tl/collection1/, http://127.0.0.1:28895/ogmsi/tl/collection1/] nUpdates=100
[junit4:junit4] 2> 237293 T497 C272 P28895 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=8
[junit4:junit4] 2> 237293 T479 C273 P27106 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=8
[junit4:junit4] 2> 237293 T461 C276 P12293 oasc.SolrCore.execute [collection1] webapp=/ogmsi/tl path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=8
[junit4:junit4] 2> 237294 T449 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:30366/ogmsi/tl Received 5 versions from 127.0.0.1:28895/ogmsi/tl/collection1/
[junit4:junit4] 2> 237295 T449 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:30366/ogmsi/tl Our versions are newer. ourLowThreshold=1436541495114989568 otherHigh=1436541495200972800
[junit4:junit4] 2> 237295 T449 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:30366/ogmsi/tl Received 4 versions from 127.0.0.1:27106/ogmsi/tl/collection1/
[junit4:junit4] 2> 237295 T449 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:30366/ogmsi/tl Our versions ar
[...truncated too long message...]
] 2> 2072242 T2570 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> 2072242 T2570 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2073070 T2512 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2073070 T2512 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2073073 T2512 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@240045bf
[junit4:junit4] 2> 2073079 T2512 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=10,adds=10,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=52,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 2073080 T2512 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 2073081 T2512 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 2073081 T2512 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> ASYNC NEW_CORE C771 name=collection1 org.apache.solr.core.SolrCore@240045bf url=http://127.0.0.1:47489/collection1 node=127.0.0.1:47489_ C771_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47489_, base_url=http://127.0.0.1:47489, leader=true}
[junit4:junit4] 2> 2073083 T2512 C771 P47489 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5f575e9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e2e58d9),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5f575e9c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e2e58d9),segFN=segments_5,generation=5}
[junit4:junit4] 2> 2073084 T2512 C771 P47489 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 2073086 T2512 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 2073087 T2512 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 2073087 T2512 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369994529299/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369994529299/jetty4;done=false>>]
[junit4:junit4] 2> 2073088 T2512 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369994529299/jetty4
[junit4:junit4] 2> 2073088 T2512 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369994529299/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369994529299/jetty4/index;done=false>>]
[junit4:junit4] 2> 2073089 T2512 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369994529299/jetty4/index
[junit4:junit4] 2> 2073090 T2634 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89783961472663564-127.0.0.1:47489_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 2073092 T2512 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 2073164 T2512 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2073165 T2512 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:13473 13473
[junit4:junit4] 2> 2073316 T2586 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2073455 T2586 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> 2073455 T2586 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2073456 T2512 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 56166
[junit4:junit4] 2> !!!! WARNING: best effort to remove /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-1369994529299 FAILED !!!!!
[junit4:junit4] 2> 2073457 T2512 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2073458 T2512 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:13473 13473
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=2FC1E187373C5811 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=fr -Dtests.timezone=Asia/Yekaterinburg -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 35.9s J0 | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:38300 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([2FC1E187373C5811:AE276F9F4063382D]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 2073478 T2512 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 35876 T2511 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> 2074392 T2603 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2074392 T2603 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> 2074392 T2603 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=fr, timezone=Asia/Yekaterinburg
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=139892240,total=459276288
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrCoreTest, AutoCommitTest, LegacyHTMLStripCharFilterTest, TestStressRecovery, MinimalSchemaTest, TestConfig, ZkControllerTest, DistributedTermsComponentTest, AlternateDirectoryTest, TestJoin, SpatialFilterTest, FileBasedSpellCheckerTest, IndexSchemaTest, DocumentBuilderTest, TestFunctionQuery, TestSearchPerf, TestQuerySenderListener, TestSolrQueryParser, SOLR749Test, BinaryUpdateRequestHandlerTest, TestRemoteStreaming, TestQueryUtils, OverseerCollectionProcessorTest, TestFieldCollectionResource, TestFieldTypeCollectionResource, TestSweetSpotSimilarityFactory, QueryElevationComponentTest, SyncSliceTest, TestManagedSchema, DistributedQueryElevationComponentTest, DateFieldTest, SimpleFacetsTest, ShowFileRequestHandlerTest, CoreAdminHandlerTest, TestLRUCache, LukeRequestHandlerTest, ClusterStateUpdateTest, TestFuzzyAnalyzedSuggestions, LeaderElectionTest, SoftAutoCommitTest, TestSurroundQueryParser, DocValuesTest, TestSchemaResource, TestPerFieldSimilarity, TestIBSimilarityFactory, SliceStateUpdateTest, TestSort, SchemaVersionSpecificBehaviorTest, PrimUtilsTest, CircularListTest, BasicFunctionalityTest, TestClassNameShortening, TestWriterPerf, JsonLoaderTest, TestCoreContainer, TestSolrDeletionPolicy2, AliasIntegrationTest, RegexBoostProcessorTest, TestGroupingSearch, PreAnalyzedUpdateProcessorTest, TestRandomDVFaceting, BasicDistributedZkTest, ZkCLITest, RecoveryZkTest, ChaosMonkeyShardSplitTest, BadComponentTest, UnloadDistributedZkTest, ShardSplitTest]
[junit4:junit4] Completed on J0 in 36.92s, 1 test, 1 error <<< FAILURES!
[...truncated 25 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:380: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:360: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:1240: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:884: There were test failures: 295 suites, 1232 tests, 1 error, 1 failure, 13 ignored (7 assumptions)
Total time: 57 minutes 21 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure