Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/589/
1 tests failed. FAILED: org.apache.solr.cloud.MultiThreadedOCPTest.testDistribSearch Error Message: We have a failed SPLITSHARD task Stack Trace: java.lang.AssertionError: We have a failed SPLITSHARD task at __randomizedtesting.SeedInfo.seed([1498AB7BD9E81E86:957E2563AEB77EBA]:0) at org.junit.Assert.fail(Assert.java:93) at org.junit.Assert.assertTrue(Assert.java:43) at org.apache.solr.cloud.MultiThreadedOCPTest.testTaskExclusivity(MultiThreadedOCPTest.java:125) at org.apache.solr.cloud.MultiThreadedOCPTest.doTest(MultiThreadedOCPTest.java:71) at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:867) 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:606) at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877) 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:65) 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:365) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836) at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738) at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783) 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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) 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:65) 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:365) at java.lang.Thread.run(Thread.java:745) Build Log: [...truncated 12031 lines...] [junit4] Suite: org.apache.solr.cloud.MultiThreadedOCPTest [junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/init-core-data-001 [junit4] 2> 2598738 T3771 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (false) [junit4] 2> 2598739 T3771 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: / [junit4] 2> 2598742 T3771 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch [junit4] 2> 2598743 T3771 oasc.ZkTestServer.run STARTING ZK TEST SERVER [junit4] 1> client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 2598744 T3772 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server [junit4] 2> 2598844 T3771 oasc.ZkTestServer.run start zk server on port:20967 [junit4] 2> 2598845 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2598849 T3778 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@61d702b4 name:ZooKeeperConnection Watcher:127.0.0.1:20967 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2598849 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2598850 T3771 oascc.SolrZkClient.makePath makePath: /solr [junit4] 2> 2598853 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2598854 T3780 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@46724c7a name:ZooKeeperConnection Watcher:127.0.0.1:20967/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2598854 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2598854 T3771 oascc.SolrZkClient.makePath makePath: /collections/collection1 [junit4] 2> 2598856 T3771 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards [junit4] 2> 2598858 T3771 oascc.SolrZkClient.makePath makePath: /collections/control_collection [junit4] 2> 2598859 T3771 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards [junit4] 2> 2598861 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml [junit4] 2> 2598862 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml [junit4] 2> 2598865 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml [junit4] 2> 2598865 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml [junit4] 2> 2598868 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml [junit4] 2> 2598868 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml [junit4] 2> 2598870 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt [junit4] 2> 2598871 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt [junit4] 2> 2598873 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt [junit4] 2> 2598873 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt [junit4] 2> 2598875 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml [junit4] 2> 2598876 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml [junit4] 2> 2598878 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml [junit4] 2> 2598878 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml [junit4] 2> 2598880 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json [junit4] 2> 2598881 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json [junit4] 2> 2598883 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt [junit4] 2> 2598884 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt [junit4] 2> 2598885 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt [junit4] 2> 2598886 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt [junit4] 2> 2598888 T3771 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt [junit4] 2> 2598889 T3771 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt [junit4] 2> 2600098 T3771 oejs.Server.doStart jetty-8.1.10.v20130312 [junit4] 2> 2600101 T3771 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:29655 [junit4] 2> 2600102 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() [junit4] 2> 2600102 T3771 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx) [junit4] 2> 2600102 T3771 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002 [junit4] 2> 2600103 T3771 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/' [junit4] 2> 2600133 T3771 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/solr.xml [junit4] 2> 2600185 T3771 oasc.CoreContainer.<init> New CoreContainer 1845206877 [junit4] 2> 2600186 T3771 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/] [junit4] 2> 2600187 T3771 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000 [junit4] 2> 2600187 T3771 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: [junit4] 2> 2600187 T3771 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000 [junit4] 2> 2600187 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20 [junit4] 2> 2600188 T3771 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0 [junit4] 2> 2600188 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647 [junit4] 2> 2600188 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5 [junit4] 2> 2600188 T3771 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1 [junit4] 2> 2600188 T3771 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false [junit4] 2> 2600189 T3771 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false [junit4] 2> 2600189 T3771 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory [junit4] 2> 2600189 T3771 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)] [junit4] 2> 2600190 T3771 oasc.CoreContainer.load Host Name: 127.0.0.1 [junit4] 2> 2600190 T3771 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:20967/solr [junit4] 2> 2600190 T3771 oasc.ZkController.checkChrootPath zkHost includes chroot [junit4] 2> 2600191 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2600192 T3791 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@229bcb14 name:ZooKeeperConnection Watcher:127.0.0.1:20967 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2600193 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2600194 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2600195 T3793 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c8d3f38 name:ZooKeeperConnection Watcher:127.0.0.1:20967/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2600195 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2600196 T3771 oascc.SolrZkClient.makePath makePath: /overseer/queue [junit4] 2> 2600197 T3771 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work [junit4] 2> 2600199 T3771 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running [junit4] 2> 2600200 T3771 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed [junit4] 2> 2600201 T3771 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure [junit4] 2> 2600203 T3771 oascc.SolrZkClient.makePath makePath: /live_nodes [junit4] 2> 2600204 T3771 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29655_ [junit4] 2> 2600204 T3771 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:29655_ [junit4] 2> 2600205 T3771 oascc.SolrZkClient.makePath makePath: /overseer_elect [junit4] 2> 2600206 T3771 oascc.SolrZkClient.makePath makePath: /overseer_elect/election [junit4] 2> 2600208 T3771 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:29655_ [junit4] 2> 2600208 T3771 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader [junit4] 2> 2600209 T3771 oasc.Overseer.start Overseer (id=92207517014032387-127.0.0.1:29655_-n_0000000000) starting [junit4] 2> 2600211 T3771 oascc.SolrZkClient.makePath makePath: /overseer/queue-work [junit4] 2> 2600215 T3795 oasc.OverseerCollectionProcessor.run Process current queue of collection creations [junit4] 2> 2600215 T3771 oascc.SolrZkClient.makePath makePath: /clusterstate.json [junit4] 2> 2600216 T3771 oascc.SolrZkClient.makePath makePath: /aliases.json [junit4] 2> 2600217 T3771 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... [junit4] 2> 2600218 T3794 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue [junit4] 2> 2600222 T3796 oasc.ZkController.publish publishing core=collection1 state=down collection=control_collection [junit4] 2> 2600222 T3796 oasc.ZkController.publish numShards not found on descriptor - reading it from system property [junit4] 2> 2600222 T3796 oasc.ZkController.waitForCoreNodeName look for our core node name [junit4] 2> 2600223 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2600223 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2600224 T3794 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={ [junit4] 2> "operation":"state", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:29655", [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "node_name":"127.0.0.1:29655_", [junit4] 2> "shard":null, [junit4] 2> "collection":"control_collection", [junit4] 2> "numShards":"1", [junit4] 2> "core_node_name":null} [junit4] 2> 2600224 T3794 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1] [junit4] 2> 2600224 T3794 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 [junit4] 2> 2600225 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2600226 T3797 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2601223 T3796 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1 [junit4] 2> 2601224 T3796 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection [junit4] 2> 2601225 T3796 oasc.ZkController.createCollectionZkNode Collection zkNode exists [junit4] 2> 2601225 T3796 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection [junit4] 2> 2601226 T3796 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper [junit4] 2> 2601226 T3796 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/collection1/' [junit4] 2> 2601227 T3796 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/collection1/lib/classes/' to classloader [junit4] 2> 2601228 T3796 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/collection1/lib/.svn/' to classloader [junit4] 2> 2601228 T3796 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/collection1/lib/README' to classloader [junit4] 2> 2601291 T3796 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10 [junit4] 2> 2601335 T3796 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml [junit4] 2> 2601336 T3796 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml [junit4] 2> 2601346 T3796 oass.IndexSchema.readSchema [collection1] Schema name=test [junit4] 2> 2601745 T3796 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead. [junit4] 2> 2601746 T3796 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead. [junit4] 2> 2601746 T3796 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440. [junit4] 2> 2601759 T3796 oass.IndexSchema.readSchema default search field in schema is text [junit4] 2> 2601762 T3796 oass.IndexSchema.readSchema unique key field: id [junit4] 2> 2601774 T3796 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml [junit4] 2> 2601778 T3796 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml [junit4] 2> 2601788 T3796 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json [junit4] 2> 2601789 T3796 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE [junit4] 2> 2601789 T3796 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING [junit4] 2> 2601789 T3796 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json [junit4] 2> 2601790 T3796 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE [junit4] 2> 2601790 T3796 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING [junit4] 2> 2601790 T3796 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection control_collection [junit4] 2> 2601790 T3796 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory [junit4] 2> 2601791 T3796 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-002/collection1/, dataDir=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-001/control/data/ [junit4] 2> 2601791 T3796 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@34ae40d3 [junit4] 2> 2601792 T3796 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-001/control/data [junit4] 2> 2601792 T3796 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-001/control/data/index/ [junit4] 2> 2601792 T3796 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-001/control/data/index' doesn't exist. Creating new index... [junit4] 2> 2601793 T3796 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-001/control/data/index [junit4] 2> 2601793 T3796 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=39, maxMergedSegmentMB=13.591796875, floorSegmentMB=2.1748046875, forceMergeDeletesPctAllowed=21.363720158407794, segmentsPerTier=19.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2185607102173476 [junit4] 2> 2601794 T3796 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1 [junit4] 2> commit{dir=MockDirectoryWrapper(RateLimitedDirectoryWrapper(RAMDirectory@53b85955 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4e4e3aaa)),segFN=segments_1,generation=1} [junit4] 2> 2601794 T3796 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1 [junit4] 2> 2601798 T3796 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib" [junit4] 2> 2601798 T3796 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe" [junit4] 2> 2601798 T3796 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe" [junit4] 2> 2601799 T3796 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig" [junit4] 2> 2601799 T3796 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig" [junit4] 2> 2601799 T3796 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit" [junit4] 2> 2601800 T3796 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 2601800 T3796 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 2601800 T3796 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default [junit4] 2> 2601801 T3796 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler [junit4] 2> 2601801 T3796 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler [junit4] 2> 2601801 T3796 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler [junit4] 2> 2601802 T3796 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler [junit4] 2> 2601802 T3796 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler [junit4] 2> 2601802 T3796 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4] 2> 2601803 T3796 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler [junit4] 2> 2601821 T3796 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60 [junit4] 2> 2601827 T3796 oasu.CommitTracker.<init> Hard AutoCommit: disabled [junit4] 2> 2601827 T3796 oasu.CommitTracker.<init> Soft AutoCommit: disabled [junit4] 2> 2601828 T3796 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=33, maxMergedSegmentMB=35.126953125, floorSegmentMB=0.845703125, forceMergeDeletesPctAllowed=4.5515110665894065, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.26227905101379545 [junit4] 2> 2601828 T3796 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1 [junit4] 2> commit{dir=MockDirectoryWrapper(RateLimitedDirectoryWrapper(RAMDirectory@53b85955 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4e4e3aaa)),segFN=segments_1,generation=1} [junit4] 2> 2601828 T3796 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1 [junit4] 2> 2601829 T3796 oass.SolrIndexSearcher.<init> Opening Searcher@5009611b[collection1] main [junit4] 2> 2601829 T3796 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection [junit4] 2> 2601830 T3796 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper [junit4] 2> 2601830 T3796 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1 [junit4] 2> 2601830 T3796 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2601831 T3796 oasr.RestManager.init Initializing RestManager with initArgs: {} [junit4] 2> 2601831 T3796 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2601831 T3796 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream No data found for znode /configs/conf1/_rest_managed.json [junit4] 2> 2601832 T3796 oasr.ManagedResourceStorage.load Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2601832 T3796 oascc.SolrZkClient.makePath makePath: /configs/conf1/_rest_managed.json [junit4] 2> 2601834 T3796 oasr.ManagedResourceStorage$ZooKeeperStorageIO$1.close Wrote 38 bytes to new znode /configs/conf1/_rest_managed.json [junit4] 2> 2601834 T3796 oasr.ManagedResourceStorage$JsonStorage.store Saved JSON object to path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2601835 T3796 oasr.RestManager.init Initializing 0 registered ManagedResources [junit4] 2> 2601837 T3798 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5009611b[collection1] main{StandardDirectoryReader(segments_1:1:nrt)} [junit4] 2> 2601839 T3796 oasc.CoreContainer.registerCore registering core: collection1 [junit4] 2> 2601840 T3801 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:29655 collection:control_collection shard:shard1 [junit4] 2> 2601840 T3771 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0 [junit4] 2> 2601841 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done [junit4] 2> 2601841 T3801 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election [junit4] 2> 2601842 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2601843 T3803 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e8616d8 name:ZooKeeperConnection Watcher:127.0.0.1:20967/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2601844 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2601844 T3771 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... [junit4] 2> 2601846 T3801 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1 [junit4] 2> 2601846 T3771 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false [junit4] 2> 2601847 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2601847 T3801 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue. [junit4] 2> 2601847 T3801 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync [junit4] 2> ASYNC NEW_CORE C1250 name=collection1 org.apache.solr.core.SolrCore@6b9b70d0 url=http://127.0.0.1:29655/collection1 node=127.0.0.1:29655_ C1250_STATE=coll:control_collection core:collection1 props:{state=down, base_url=http://127.0.0.1:29655, core=collection1, node_name=127.0.0.1:29655_} [junit4] 2> 2601848 T3801 C1250 P29655 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:29655/collection1/ [junit4] 2> 2601848 T3801 C1250 P29655 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me [junit4] 2> 2601848 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2601848 T3801 C1250 P29655 oasc.SyncStrategy.syncToMe http://127.0.0.1:29655/collection1/ has no replicas [junit4] 2> 2601849 T3801 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:29655/collection1/ shard1 [junit4] 2> 2601849 T3801 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1 [junit4] 2> 2601850 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2601851 T3797 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2601851 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2601854 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2601855 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2601957 T3797 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2601957 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2602006 T3801 oasc.ZkController.register We are http://127.0.0.1:29655/collection1/ and leader is http://127.0.0.1:29655/collection1/ [junit4] 2> 2602007 T3801 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29655 [junit4] 2> 2602007 T3801 oasc.ZkController.checkRecovery I am the leader, no recovery necessary [junit4] 2> 2602007 T3801 oasc.ZkController.publish publishing core=collection1 state=active collection=control_collection [junit4] 2> 2602007 T3801 oasc.ZkController.publish numShards not found on descriptor - reading it from system property [junit4] 2> 2602008 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2602008 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2602009 T3801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2602009 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2602010 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2602010 T3794 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={ [junit4] 2> "operation":"state", [junit4] 2> "state":"active", [junit4] 2> "base_url":"http://127.0.0.1:29655", [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "node_name":"127.0.0.1:29655_", [junit4] 2> "shard":"shard1", [junit4] 2> "collection":"control_collection", [junit4] 2> "numShards":"2", [junit4] 2> "core_node_name":"core_node1"} [junit4] 2> 2602012 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2602113 T3806 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2602113 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1) [junit4] 2> 2602950 T3771 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 1 [junit4] 2> 2602951 T3771 oejs.Server.doStart jetty-8.1.10.v20130312 [junit4] 2> 2602954 T3771 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:47424 [junit4] 2> 2602954 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() [junit4] 2> 2602954 T3771 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx) [junit4] 2> 2602954 T3771 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003 [junit4] 2> 2602955 T3771 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/' [junit4] 2> 2602984 T3771 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/solr.xml [junit4] 2> 2603035 T3771 oasc.CoreContainer.<init> New CoreContainer 1908158125 [junit4] 2> 2603035 T3771 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/] [junit4] 2> 2603036 T3771 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000 [junit4] 2> 2603036 T3771 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: [junit4] 2> 2603036 T3771 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000 [junit4] 2> 2603037 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20 [junit4] 2> 2603037 T3771 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0 [junit4] 2> 2603037 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647 [junit4] 2> 2603037 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5 [junit4] 2> 2603037 T3771 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1 [junit4] 2> 2603038 T3771 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false [junit4] 2> 2603038 T3771 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false [junit4] 2> 2603038 T3771 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory [junit4] 2> 2603039 T3771 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)] [junit4] 2> 2603039 T3771 oasc.CoreContainer.load Host Name: 127.0.0.1 [junit4] 2> 2603039 T3771 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:20967/solr [junit4] 2> 2603039 T3771 oasc.ZkController.checkChrootPath zkHost includes chroot [junit4] 2> 2603040 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2603041 T3817 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@799c9a30 name:ZooKeeperConnection Watcher:127.0.0.1:20967 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2603042 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2603044 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2603044 T3819 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62776e5c name:ZooKeeperConnection Watcher:127.0.0.1:20967/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2603045 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2603049 T3771 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... [junit4] 2> 2604051 T3771 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47424_ [junit4] 2> 2604052 T3771 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47424_ [junit4] 2> 2604054 T3806 oascc.ZkStateReader$3.process Updating live nodes... (2) [junit4] 2> 2604055 T3820 oascc.ZkStateReader$3.process Updating live nodes... (2) [junit4] 2> 2604054 T3804 oascc.ZkStateReader$3.process Updating live nodes... (2) [junit4] 2> 2604061 T3821 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1 [junit4] 2> 2604062 T3821 oasc.ZkController.publish numShards not found on descriptor - reading it from system property [junit4] 2> 2604062 T3821 oasc.ZkController.waitForCoreNodeName look for our core node name [junit4] 2> 2604062 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2604062 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2604062 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2604064 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2604064 T3794 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={ [junit4] 2> "operation":"state", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:47424", [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "node_name":"127.0.0.1:47424_", [junit4] 2> "shard":null, [junit4] 2> "collection":"collection1", [junit4] 2> "numShards":"2", [junit4] 2> "core_node_name":null} [junit4] 2> 2604065 T3794 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2] [junit4] 2> 2604065 T3794 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2 [junit4] 2> 2604067 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2604067 T3806 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2604067 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2604067 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2605063 T3821 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1 [junit4] 2> 2605064 T3821 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1 [junit4] 2> 2605065 T3821 oasc.ZkController.createCollectionZkNode Collection zkNode exists [junit4] 2> 2605065 T3821 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1 [junit4] 2> 2605066 T3821 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper [junit4] 2> 2605066 T3821 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/' [junit4] 2> 2605085 T3821 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/lib/classes/' to classloader [junit4] 2> 2605092 T3821 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/lib/README' to classloader [junit4] 2> 2605099 T3821 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/lib/.svn/' to classloader [junit4] 2> 2605406 T3821 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10 [junit4] 2> 2605516 T3821 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml [junit4] 2> 2605518 T3821 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml [junit4] 2> 2605538 T3821 oass.IndexSchema.readSchema [collection1] Schema name=test [junit4] 2> 2606493 T3821 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead. [junit4] 2> 2606494 T3821 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead. [junit4] 2> 2606495 T3821 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440. [junit4] 2> 2606530 T3821 oass.IndexSchema.readSchema default search field in schema is text [junit4] 2> 2606537 T3821 oass.IndexSchema.readSchema unique key field: id [junit4] 2> 2606561 T3821 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml [junit4] 2> 2606570 T3821 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml [junit4] 2> 2606579 T3821 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json [junit4] 2> 2606581 T3821 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE [junit4] 2> 2606581 T3821 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING [junit4] 2> 2606582 T3821 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json [junit4] 2> 2606583 T3821 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE [junit4] 2> 2606583 T3821 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING [junit4] 2> 2606584 T3821 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1 [junit4] 2> 2606584 T3821 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory [junit4] 2> 2606584 T3821 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/, dataDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/data/ [junit4] 2> 2606585 T3821 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@34ae40d3 [junit4] 2> 2606586 T3821 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/data [junit4] 2> 2606587 T3821 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/data/index/ [junit4] 2> 2606587 T3821 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/data/index' doesn't exist. Creating new index... [junit4] 2> 2606587 T3821 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-003/collection1/data/index [junit4] 2> 2606588 T3821 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=39, maxMergedSegmentMB=13.591796875, floorSegmentMB=2.1748046875, forceMergeDeletesPctAllowed=21.363720158407794, segmentsPerTier=19.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2185607102173476 [junit4] 2> 2606589 T3821 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1 [junit4] 2> commit{dir=MockDirectoryWrapper(RateLimitedDirectoryWrapper(RAMDirectory@364c8ab9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@275c359d)),segFN=segments_1,generation=1} [junit4] 2> 2606590 T3821 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1 [junit4] 2> 2606595 T3821 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib" [junit4] 2> 2606596 T3821 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe" [junit4] 2> 2606596 T3821 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe" [junit4] 2> 2606596 T3821 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig" [junit4] 2> 2606597 T3821 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig" [junit4] 2> 2606597 T3821 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit" [junit4] 2> 2606598 T3821 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 2606599 T3821 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 2606599 T3821 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default [junit4] 2> 2606600 T3821 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler [junit4] 2> 2606601 T3821 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler [junit4] 2> 2606601 T3821 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler [junit4] 2> 2606602 T3821 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler [junit4] 2> 2606602 T3821 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler [junit4] 2> 2606603 T3821 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4] 2> 2606604 T3821 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler [junit4] 2> 2606657 T3821 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60 [junit4] 2> 2606673 T3821 oasu.CommitTracker.<init> Hard AutoCommit: disabled [junit4] 2> 2606673 T3821 oasu.CommitTracker.<init> Soft AutoCommit: disabled [junit4] 2> 2606674 T3821 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=33, maxMergedSegmentMB=35.126953125, floorSegmentMB=0.845703125, forceMergeDeletesPctAllowed=4.5515110665894065, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.26227905101379545 [junit4] 2> 2606675 T3821 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1 [junit4] 2> commit{dir=MockDirectoryWrapper(RateLimitedDirectoryWrapper(RAMDirectory@364c8ab9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@275c359d)),segFN=segments_1,generation=1} [junit4] 2> 2606675 T3821 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1 [junit4] 2> 2606675 T3821 oass.SolrIndexSearcher.<init> Opening Searcher@4d95fdf8[collection1] main [junit4] 2> 2606676 T3821 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1 [junit4] 2> 2606677 T3821 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper [junit4] 2> 2606677 T3821 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1 [junit4] 2> 2606678 T3821 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2606679 T3821 oasr.RestManager.init Initializing RestManager with initArgs: {} [junit4] 2> 2606679 T3821 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2606680 T3821 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json [junit4] 2> 2606681 T3821 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2606681 T3821 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed [junit4] 2> 2606681 T3821 oasr.RestManager.init Initializing 0 registered ManagedResources [junit4] 2> 2606687 T3822 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4d95fdf8[collection1] main{StandardDirectoryReader(segments_1:1:nrt)} [junit4] 2> 2606689 T3821 oasc.CoreContainer.registerCore registering core: collection1 [junit4] 2> 2606690 T3825 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47424 collection:collection1 shard:shard2 [junit4] 2> 2606691 T3771 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0 [junit4] 2> 2606691 T3825 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election [junit4] 2> 2606691 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done [junit4] 2> 2606706 T3825 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2 [junit4] 2> 2606711 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606712 T3825 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue. [junit4] 2> 2606713 T3825 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync [junit4] 2> ASYNC NEW_CORE C1251 name=collection1 org.apache.solr.core.SolrCore@7f132c21 url=http://127.0.0.1:47424/collection1 node=127.0.0.1:47424_ C1251_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:47424, core=collection1, node_name=127.0.0.1:47424_} [junit4] 2> 2606713 T3825 C1251 P47424 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47424/collection1/ [junit4] 2> 2606713 T3825 C1251 P47424 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me [junit4] 2> 2606714 T3825 C1251 P47424 oasc.SyncStrategy.syncToMe http://127.0.0.1:47424/collection1/ has no replicas [junit4] 2> 2606714 T3825 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47424/collection1/ shard2 [junit4] 2> 2606714 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2606715 T3825 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2 [junit4] 2> 2606724 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606726 T3806 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606727 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606727 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606733 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2606737 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606842 T3806 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606842 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606843 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606884 T3825 oasc.ZkController.register We are http://127.0.0.1:47424/collection1/ and leader is http://127.0.0.1:47424/collection1/ [junit4] 2> 2606885 T3825 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47424 [junit4] 2> 2606885 T3825 oasc.ZkController.checkRecovery I am the leader, no recovery necessary [junit4] 2> 2606885 T3825 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1 [junit4] 2> 2606886 T3825 oasc.ZkController.publish numShards not found on descriptor - reading it from system property [junit4] 2> 2606888 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606888 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606888 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606889 T3825 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2606890 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2606891 T3794 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={ [junit4] 2> "operation":"state", [junit4] 2> "state":"active", [junit4] 2> "base_url":"http://127.0.0.1:47424", [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "node_name":"127.0.0.1:47424_", [junit4] 2> "shard":"shard2", [junit4] 2> "collection":"collection1", [junit4] 2> "numShards":"2", [junit4] 2> "core_node_name":"core_node1"} [junit4] 2> 2606894 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2606996 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606996 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2606996 T3805 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2) [junit4] 2> 2608243 T3771 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 2 [junit4] 2> 2608244 T3771 oejs.Server.doStart jetty-8.1.10.v20130312 [junit4] 2> 2608247 T3771 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16313 [junit4] 2> 2608247 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() [junit4] 2> 2608248 T3771 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx) [junit4] 2> 2608248 T3771 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004 [junit4] 2> 2608248 T3771 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/' [junit4] 2> 2608283 T3771 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/solr.xml [junit4] 2> 2608335 T3771 oasc.CoreContainer.<init> New CoreContainer 549509802 [junit4] 2> 2608335 T3771 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/] [junit4] 2> 2608336 T3771 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000 [junit4] 2> 2608336 T3771 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: [junit4] 2> 2608337 T3771 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000 [junit4] 2> 2608337 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20 [junit4] 2> 2608337 T3771 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0 [junit4] 2> 2608337 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647 [junit4] 2> 2608338 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5 [junit4] 2> 2608338 T3771 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1 [junit4] 2> 2608338 T3771 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false [junit4] 2> 2608338 T3771 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false [junit4] 2> 2608339 T3771 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory [junit4] 2> 2608339 T3771 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)] [junit4] 2> 2608339 T3771 oasc.CoreContainer.load Host Name: 127.0.0.1 [junit4] 2> 2608339 T3771 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:20967/solr [junit4] 2> 2608340 T3771 oasc.ZkController.checkChrootPath zkHost includes chroot [junit4] 2> 2608340 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2608342 T3836 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5553dfb2 name:ZooKeeperConnection Watcher:127.0.0.1:20967 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2608343 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2608344 T3771 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper [junit4] 2> 2608345 T3838 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16f1b09e name:ZooKeeperConnection Watcher:127.0.0.1:20967/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None [junit4] 2> 2608345 T3771 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper [junit4] 2> 2608350 T3771 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... [junit4] 2> 2609353 T3771 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16313_ [junit4] 2> 2609354 T3771 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16313_ [junit4] 2> 2609357 T3804 oascc.ZkStateReader$3.process Updating live nodes... (3) [junit4] 2> 2609357 T3805 oascc.ZkStateReader$3.process Updating live nodes... (3) [junit4] 2> 2609357 T3820 oascc.ZkStateReader$3.process Updating live nodes... (3) [junit4] 2> 2609357 T3839 oascc.ZkStateReader$3.process Updating live nodes... (3) [junit4] 2> 2609364 T3840 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1 [junit4] 2> 2609364 T3840 oasc.ZkController.publish numShards not found on descriptor - reading it from system property [junit4] 2> 2609365 T3840 oasc.ZkController.waitForCoreNodeName look for our core node name [junit4] 2> 2609365 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2609365 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2609365 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2609366 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2609367 T3794 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={ [junit4] 2> "operation":"state", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:16313", [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "node_name":"127.0.0.1:16313_", [junit4] 2> "shard":null, [junit4] 2> "collection":"collection1", [junit4] 2> "numShards":"2", [junit4] 2> "core_node_name":null} [junit4] 2> 2609367 T3794 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2 [junit4] 2> 2609367 T3794 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1 [junit4] 2> 2609369 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2609370 T3805 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2609370 T3839 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2609370 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2609370 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2610365 T3840 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1 [junit4] 2> 2610366 T3840 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1 [junit4] 2> 2610366 T3840 oasc.ZkController.createCollectionZkNode Collection zkNode exists [junit4] 2> 2610366 T3840 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1 [junit4] 2> 2610367 T3840 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper [junit4] 2> 2610367 T3840 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/' [junit4] 2> 2610369 T3840 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/lib/README' to classloader [junit4] 2> 2610369 T3840 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/lib/classes/' to classloader [junit4] 2> 2610370 T3840 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/lib/.svn/' to classloader [junit4] 2> 2610429 T3840 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10 [junit4] 2> 2610485 T3840 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml [junit4] 2> 2610486 T3840 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml [junit4] 2> 2610496 T3840 oass.IndexSchema.readSchema [collection1] Schema name=test [junit4] 2> 2610910 T3840 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead. [junit4] 2> 2610911 T3840 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead. [junit4] 2> 2610912 T3840 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440. [junit4] 2> 2610926 T3840 oass.IndexSchema.readSchema default search field in schema is text [junit4] 2> 2610929 T3840 oass.IndexSchema.readSchema unique key field: id [junit4] 2> 2610941 T3840 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml [junit4] 2> 2610945 T3840 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml [junit4] 2> 2610949 T3840 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json [junit4] 2> 2610950 T3840 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE [junit4] 2> 2610950 T3840 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING [junit4] 2> 2610950 T3840 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json [junit4] 2> 2610951 T3840 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE [junit4] 2> 2610951 T3840 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING [junit4] 2> 2610951 T3840 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1 [junit4] 2> 2610952 T3840 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory [junit4] 2> 2610952 T3840 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/, dataDir=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/data/ [junit4] 2> 2610952 T3840 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@34ae40d3 [junit4] 2> 2610953 T3840 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/data [junit4] 2> 2610953 T3840 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/data/index/ [junit4] 2> 2610953 T3840 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/data/index' doesn't exist. Creating new index... [junit4] 2> 2610954 T3840 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-004/collection1/data/index [junit4] 2> 2610954 T3840 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=39, maxMergedSegmentMB=13.591796875, floorSegmentMB=2.1748046875, forceMergeDeletesPctAllowed=21.363720158407794, segmentsPerTier=19.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2185607102173476 [junit4] 2> 2610955 T3840 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1 [junit4] 2> commit{dir=MockDirectoryWrapper(RateLimitedDirectoryWrapper(RAMDirectory@5b588420 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1eb2f61f)),segFN=segments_1,generation=1} [junit4] 2> 2610955 T3840 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1 [junit4] 2> 2610960 T3840 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib" [junit4] 2> 2610960 T3840 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe" [junit4] 2> 2610961 T3840 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe" [junit4] 2> 2610961 T3840 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig" [junit4] 2> 2610961 T3840 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig" [junit4] 2> 2610961 T3840 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit" [junit4] 2> 2610962 T3840 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 2610962 T3840 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit" [junit4] 2> 2610963 T3840 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default [junit4] 2> 2610963 T3840 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler [junit4] 2> 2610964 T3840 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler [junit4] 2> 2610964 T3840 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler [junit4] 2> 2610964 T3840 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler [junit4] 2> 2610965 T3840 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler [junit4] 2> 2610965 T3840 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers [junit4] 2> 2610966 T3840 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler [junit4] 2> 2610987 T3840 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60 [junit4] 2> 2610992 T3840 oasu.CommitTracker.<init> Hard AutoCommit: disabled [junit4] 2> 2610992 T3840 oasu.CommitTracker.<init> Soft AutoCommit: disabled [junit4] 2> 2610993 T3840 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=33, maxMergedSegmentMB=35.126953125, floorSegmentMB=0.845703125, forceMergeDeletesPctAllowed=4.5515110665894065, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.26227905101379545 [junit4] 2> 2610994 T3840 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1 [junit4] 2> commit{dir=MockDirectoryWrapper(RateLimitedDirectoryWrapper(RAMDirectory@5b588420 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@1eb2f61f)),segFN=segments_1,generation=1} [junit4] 2> 2610994 T3840 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1 [junit4] 2> 2610994 T3840 oass.SolrIndexSearcher.<init> Opening Searcher@4120b6fe[collection1] main [junit4] 2> 2610995 T3840 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1 [junit4] 2> 2610995 T3840 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper [junit4] 2> 2610996 T3840 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1 [junit4] 2> 2610996 T3840 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 2610996 T3840 oasr.RestManager.init Initializing RestManager with initArgs: {} [junit4] 2> 2610997 T3840 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2610997 T3840 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json [junit4] 2> 2610998 T3840 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 2610998 T3840 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed [junit4] 2> 2610998 T3840 oasr.RestManager.init Initializing 0 registered ManagedResources [junit4] 2> 2611002 T3841 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4120b6fe[collection1] main{StandardDirectoryReader(segments_1:1:nrt)} [junit4] 2> 2611004 T3840 oasc.CoreContainer.registerCore registering core: collection1 [junit4] 2> 2611005 T3844 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:16313 collection:collection1 shard:shard1 [junit4] 2> 2611005 T3771 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0 [junit4] 2> 2611006 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done [junit4] 2> 2611006 T3844 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election [junit4] 2> 2611010 T3844 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1 [junit4] 2> 2611011 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611011 T3844 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue. [junit4] 2> 2611012 T3844 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync [junit4] 2> ASYNC NEW_CORE C1252 name=collection1 org.apache.solr.core.SolrCore@576dbe87 url=http://127.0.0.1:16313/collection1 node=127.0.0.1:16313_ C1252_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:16313, core=collection1, node_name=127.0.0.1:16313_} [junit4] 2> 2611012 T3844 C1252 P16313 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:16313/collection1/ [junit4] 2> 2611012 T3844 C1252 P16313 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me [junit4] 2> 2611012 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2611012 T3844 C1252 P16313 oasc.SyncStrategy.syncToMe http://127.0.0.1:16313/collection1/ has no replicas [junit4] 2> 2611013 T3844 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:16313/collection1/ shard1 [junit4] 2> 2611013 T3844 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1 [junit4] 2> 2611014 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611015 T3805 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611015 T3839 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611015 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611015 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611018 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2611020 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611121 T3805 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611122 T3839 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611121 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611121 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611169 T3844 oasc.ZkController.register We are http://127.0.0.1:16313/collection1/ and leader is http://127.0.0.1:16313/collection1/ [junit4] 2> 2611170 T3844 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16313 [junit4] 2> 2611170 T3844 oasc.ZkController.checkRecovery I am the leader, no recovery necessary [junit4] 2> 2611170 T3844 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1 [junit4] 2> 2611170 T3844 oasc.ZkController.publish numShards not found on descriptor - reading it from system property [junit4] 2> 2611171 T3805 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611172 T3844 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2611172 T3806 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611171 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611173 T3794 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... [junit4] 2> 2611174 T3794 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={ [junit4] 2> "operation":"state", [junit4] 2> "state":"active", [junit4] 2> "base_url":"http://127.0.0.1:16313", [junit4] 2> "core":"collection1", [junit4] 2> "roles":null, [junit4] 2> "node_name":"127.0.0.1:16313_", [junit4] 2> "shard":"shard1", [junit4] 2> "collection":"collection1", [junit4] 2> "numShards":"2", [junit4] 2> "core_node_name":"core_node2"} [junit4] 2> 2611175 T3797 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged [junit4] 2> 2611278 T3804 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611278 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611278 T3797 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2611278 T3839 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3) [junit4] 2> 2612059 T3771 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 3 [junit4] 2> 2612060 T3771 oejs.Server.doStart jetty-8.1.10.v20130312 [junit4] 2> 2612062 T3771 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16338 [junit4] 2> 2612062 T3771 oass.SolrDispatchFilter.init SolrDispatchFilter.init() [junit4] 2> 2612063 T3771 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx) [junit4] 2> 2612063 T3771 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-005 [junit4] 2> 2612063 T3771 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-005/' [junit4] 2> 2612092 T3771 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-005/solr.xml [junit4] 2> 2612141 T3771 oasc.CoreContainer.<init> New CoreContainer 100020689 [junit4] 2> 2612142 T3771 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-005/] [junit4] 2> 2612143 T3771 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000 [junit4] 2> 2612143 T3771 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: [junit4] 2> 2612143 T3771 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000 [junit4] 2> 2612143 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20 [junit4] 2> 2612144 T3771 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0 [junit4] 2> 2612144 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647 [junit4] 2> 2612144 T3771 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5 [junit4] 2> 2612144 T3771 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1 [junit4] 2> 2612144 T3771 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false [junit4] 2> 2612145 T3771 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTi [...truncated too long message...] [CachedDir<<refCount=0;path=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest2_shard3_replica1/data/index;done=false>>] [junit4] 2> 2648984 T3771 oasc.CachingDirectoryFactory.close Closing directory: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest2_shard3_replica1/data/index [junit4] 2> 2648985 T3771 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest2_shard3_replica1/data [CachedDir<<refCount=0;path=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest2_shard3_replica1/data;done=false>>] [junit4] 2> 2648985 T3771 oasc.CachingDirectoryFactory.close Closing directory: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest2_shard3_replica1/data [junit4] 2> 2648985 T3771 oasc.SolrCore.close [ocptest3_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@7ac26668 [junit4] 2> 2648993 T3771 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0,transaction_logs_total_size=0,transaction_logs_total_number=0} [junit4] 2> 2648993 T3771 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState [junit4] 2> 2648994 T3771 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter [junit4] 2> 2648994 T3771 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser [junit4] 2> 2648995 T3771 oasc.SolrCore.closeSearcher [ocptest3_shard1_replica1] Closing main searcher on request. [junit4] 2> 2648995 T3771 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked [junit4] 2> 2648995 T3771 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest3_shard1_replica1/data [CachedDir<<refCount=0;path=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest3_shard1_replica1/data;done=false>>] [junit4] 2> 2648996 T3771 oasc.CachingDirectoryFactory.close Closing directory: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest3_shard1_replica1/data [junit4] 2> 2648996 T3771 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest3_shard1_replica1/data/index [CachedDir<<refCount=0;path=./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest3_shard1_replica1/data/index;done=false>>] [junit4] 2> 2648996 T3771 oasc.CachingDirectoryFactory.close Closing directory: ./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001/tempDir-006/ocptest3_shard1_replica1/data/index [junit4] 2> 2648997 T5321 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:16342_ [junit4] 2> 2648999 T5316 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK [junit4] 2> 2648999 T5323 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127) [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1155) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:302) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:299) [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:299) [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:316) [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:85) [junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:288) [junit4] 2> [junit4] 2> 2649000 T3771 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null} [junit4] 2> 2653958 T3771 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch [junit4] 2> 2653960 T3771 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:20967 20967 [junit4] 2> 2654153 T3772 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:20967 20967 [junit4] 2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory. [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=MultiThreadedOCPTest -Dtests.method=testDistribSearch -Dtests.seed=1498AB7BD9E81E86 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=es_AR -Dtests.timezone=Asia/Anadyr -Dtests.file.encoding=US-ASCII [junit4] FAILURE 55.4s J0 | MultiThreadedOCPTest.testDistribSearch <<< [junit4] > Throwable #1: java.lang.AssertionError: We have a failed SPLITSHARD task [junit4] > at __randomizedtesting.SeedInfo.seed([1498AB7BD9E81E86:957E2563AEB77EBA]:0) [junit4] > at org.apache.solr.cloud.MultiThreadedOCPTest.testTaskExclusivity(MultiThreadedOCPTest.java:125) [junit4] > at org.apache.solr.cloud.MultiThreadedOCPTest.doTest(MultiThreadedOCPTest.java:71) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:867) [junit4] > at java.lang.Thread.run(Thread.java:745) [junit4] 2> 2654176 T3771 oas.SolrTestCaseJ4.deleteCore ###deleteCore [junit4] 2> NOTE: leaving temporary files on disk at: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-1498AB7BD9E81E86-001 [junit4] 2> 55443 T3770 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s). [junit4] 2> NOTE: test params are: codec=Lucene46, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=es_AR, timezone=Asia/Anadyr [junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=189123928,total=333971456 [junit4] 2> NOTE: All tests run in this JVM: [TestStressReorder, EchoParamsTest, TestSearcherReuse, TestDFRSimilarityFactory, PluginInfoTest, TestCodecSupport, TestCloudManagedSchema, TestCloudSchemaless, BasicDistributedZkTest, TestComponentsName, WordBreakSolrSpellCheckerTest, ZkCLITest, HdfsCollectionsAPIDistributedZkTest, AnalyticsQueryTest, TestFastOutputStream, TestRandomMergePolicy, SuggesterWFSTTest, TestSolrXmlPersistence, TestMiniSolrCloudCluster, RequiredFieldsTest, TestFaceting, DirectSolrSpellCheckerTest, PathHierarchyTokenizerFactoryTest, ReplicationFactorTest, SolrCmdDistributorTest, TestHashPartitioner, TestTrie, TestRangeQuery, MBeansHandlerTest, PingRequestHandlerTest, TestComplexPhraseQParserPlugin, TestSolrDeletionPolicy1, MinimalSchemaTest, TestStandardQParsers, XsltUpdateRequestHandlerTest, FieldMutatingUpdateProcessorTest, TestBM25SimilarityFactory, TestStressVersions, TestManagedResource, SliceStateTest, TestSimpleQParserPlugin, TestClassNameShortening, TestFuzzyAnalyzedSuggestions, TestIntervalFaceting, BadCopyFieldTest, SpellPossibilityIteratorTest, SolrTestCaseJ4Test, TestMaxScoreQueryParser, TestManagedSynonymFilterFactory, TestRestManager, SimpleFacetsTest, StandardRequestHandlerTest, MergeStrategyTest, CurrencyFieldOpenExchangeTest, QueryEqualityTest, TestUtils, BadIndexSchemaTest, TestFieldResource, SolrXmlInZkTest, DistributedDebugComponentTest, ExternalFileFieldSortTest, TestSurroundQueryParser, NoCacheHeaderTest, TestSchemaResource, CollectionsAPIAsyncDistributedZkTest, TestNumberUtils, TestStressRecovery, MultiThreadedOCPTest] [junit4] Completed on J0 in 55.97s, 1 test, 1 failure <<< FAILURES! [...truncated 763 lines...] BUILD FAILED /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:474: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:447: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:45: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/extra-targets.xml:37: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build.xml:189: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/common-build.xml:496: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1299: The following error occurred while executing this line: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:923: There were test failures: 411 suites, 1705 tests, 1 failure, 50 ignored (8 assumptions) Total time: 228 minutes 52 seconds Build step 'Invoke Ant' marked build as failure Archiving artifacts Sending artifact delta relative to Lucene-Solr-NightlyTests-4.x #586 Archived 3 artifacts Archive block size is 32768 Received 0 blocks and 675968823 bytes Compression is 0.0% Took 1 min 51 sec Recording test results Email was triggered for: Failure Sending email for trigger: Failure
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org