You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/11/24 05:16:59 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 2187 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/2187/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Wrong doc count on shard1_1 expected:<129> but was:<118>
Stack Trace:
java.lang.AssertionError: Wrong doc count on shard1_1 expected:<129> but was:<118>
at __randomizedtesting.SeedInfo.seed([41B9F363CFB8DB43:C05F7D7BB8E7BB7F]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.ShardSplitTest.checkDocCountsAndShardStates(ShardSplitTest.java:478)
at org.apache.solr.cloud.ShardSplitTest.splitByUniqueKeyTest(ShardSplitTest.java:249)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:113)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:679)
Build Log:
[...truncated 9559 lines...]
[junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4] 2> 182052 T507 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /pjsa/
[junit4] 2> 182059 T507 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1385264642560
[junit4] 2> 182060 T507 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 182061 T508 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 182162 T507 oasc.ZkTestServer.run start zk server on port:44824
[junit4] 2> 182164 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 182168 T514 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6303aa37 name:ZooKeeperConnection Watcher:127.0.0.1:44824 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 182168 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 182168 T507 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 182183 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 182185 T516 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@563afc0c name:ZooKeeperConnection Watcher:127.0.0.1:44824/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 182185 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 182186 T507 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 182199 T507 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 182202 T507 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 182205 T507 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 182216 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 182217 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 182229 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4] 2> 182230 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 182335 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 182336 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 182348 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 182349 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 182353 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 182353 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 182357 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 182358 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 182361 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 182362 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml
[junit4] 2> 182382 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 182383 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 182386 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 182387 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 182390 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 182391 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 182404 T507 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 182404 T507 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 182698 T507 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 182704 T507 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:21967
[junit4] 2> 182705 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 182705 T507 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 182706 T507 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917
[junit4] 2> 182706 T507 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/'
[junit4] 2> 182744 T507 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/solr.xml
[junit4] 2> 182820 T507 oasc.CoreContainer.<init> New CoreContainer 1019513248
[junit4] 2> 182821 T507 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/]
[junit4] 2> 182823 T507 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 182824 T507 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 182824 T507 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 182825 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 182825 T507 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 182826 T507 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 182826 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 182827 T507 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 182827 T507 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 182845 T507 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 182846 T507 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 182846 T507 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 182847 T507 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44824/solr
[junit4] 2> 182848 T507 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 182849 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 182851 T527 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b27868b name:ZooKeeperConnection Watcher:127.0.0.1:44824 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 182852 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 182855 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 182865 T529 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c907aee name:ZooKeeperConnection Watcher:127.0.0.1:44824/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 182866 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 182872 T507 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 182892 T507 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 182896 T507 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 182911 T507 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:21967_pjsa
[junit4] 2> 182913 T507 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:21967_pjsa
[junit4] 2> 182924 T507 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 182947 T507 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 182954 T507 oasc.Overseer.start Overseer (id=90784703615336451-127.0.0.1:21967_pjsa-n_0000000000) starting
[junit4] 2> 182974 T507 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 182994 T531 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 182995 T507 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 183013 T507 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 183015 T507 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 183018 T530 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 183023 T532 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 183024 T532 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 183025 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 183025 T532 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 183027 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 183028 T530 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:21967/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:21967_pjsa",
[junit4] 2> "shard":null,
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "numShards":"1",
[junit4] 2> "core_node_name":null}
[junit4] 2> 183028 T530 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
[junit4] 2> 183028 T530 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 183044 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 183045 T529 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> 184027 T532 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 184027 T532 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/collection1
[junit4] 2> 184028 T532 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4] 2> 184029 T532 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 184029 T532 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
[junit4] 2> 184030 T532 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/collection1/'
[junit4] 2> 184031 T532 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/collection1/lib/classes/' to classloader
[junit4] 2> 184032 T532 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/collection1/lib/README' to classloader
[junit4] 2> 184098 T532 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 184160 T532 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 184261 T532 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 184272 T532 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 184852 T532 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 184856 T532 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 184859 T532 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 184864 T532 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 184896 T532 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 184896 T532 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.cloud.ShardSplitTest-controljetty-1385264642917/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1385264642559/control/data/
[junit4] 2> 184897 T532 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@18793536
[junit4] 2> 184898 T532 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/control/data
[junit4] 2> 184898 T532 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1385264642559/control/data/index/
[junit4] 2> 184899 T532 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1385264642559/control/data/index' doesn't exist. Creating new index...
[junit4] 2> 184899 T532 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/control/data/index
[junit4] 2> 184900 T532 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=44, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 184901 T532 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@693b004c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@5d0d9119),segFN=segments_1,generation=1}
[junit4] 2> 184902 T532 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 184907 T532 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 184907 T532 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 184908 T532 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 184908 T532 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 184908 T532 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 184909 T532 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 184910 T532 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 184910 T532 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 184910 T532 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 184911 T532 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 184912 T532 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 184912 T532 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 184913 T532 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 184913 T532 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 184914 T532 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 184915 T532 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 184924 T532 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 184931 T532 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 184931 T532 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 184932 T532 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=23, maxMergedSegmentMB=7.1552734375, floorSegmentMB=0.8935546875, forceMergeDeletesPctAllowed=20.14914291271336, segmentsPerTier=47.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.586977028415173
[junit4] 2> 184933 T532 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@693b004c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@5d0d9119),segFN=segments_1,generation=1}
[junit4] 2> 184933 T532 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 184934 T532 oass.SolrIndexSearcher.<init> Opening Searcher@6ba26eb1 main
[junit4] 2> 184938 T533 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ba26eb1 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 184940 T532 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 184941 T532 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:21967/pjsa collection:control_collection shard:shard1
[junit4] 2> 184942 T532 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4] 2> 184990 T532 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 185000 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185000 T532 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 185001 T532 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C54 name=collection1 org.apache.solr.core.SolrCore@4ff561a7 url=http://127.0.0.1:21967/pjsa/collection1 node=127.0.0.1:21967_pjsa C54_STATE=coll:control_collection core:collection1 props:{state=down, base_url=http://127.0.0.1:21967/pjsa, core=collection1, node_name=127.0.0.1:21967_pjsa}
[junit4] 2> 185001 T532 C54 P21967 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:21967/pjsa/collection1/
[junit4] 2> 185001 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 185002 T532 C54 P21967 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 185002 T532 C54 P21967 oasc.SyncStrategy.syncToMe http://127.0.0.1:21967/pjsa/collection1/ has no replicas
[junit4] 2> 185003 T532 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:21967/pjsa/collection1/ shard1
[junit4] 2> 185003 T532 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4] 2> 185018 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185040 T529 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> 185073 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 185089 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185193 T529 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> 185226 T532 oasc.ZkController.register We are http://127.0.0.1:21967/pjsa/collection1/ and leader is http://127.0.0.1:21967/pjsa/collection1/
[junit4] 2> 185226 T532 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:21967/pjsa
[junit4] 2> 185226 T532 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 185227 T532 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 185227 T532 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 185229 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185229 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185230 T532 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 185230 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185231 T507 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4] 2> 185232 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 185232 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 185233 T530 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "base_url":"http://127.0.0.1:21967/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:21967_pjsa",
[junit4] 2> "shard":"shard1",
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "numShards":"1",
[junit4] 2> "core_node_name":"core_node1"}
[junit4] 2> 185235 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 185245 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 185246 T536 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68a614a4 name:ZooKeeperConnection Watcher:127.0.0.1:44824/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 185246 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 185247 T507 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 185250 T507 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 185349 T529 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> 185349 T536 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> 185572 T507 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 185576 T507 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15671
[junit4] 2> 185577 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 185578 T507 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 185578 T507 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750
[junit4] 2> 185594 T507 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/'
[junit4] 2> 185640 T507 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/solr.xml
[junit4] 2> 185717 T507 oasc.CoreContainer.<init> New CoreContainer 1254200493
[junit4] 2> 185717 T507 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/]
[junit4] 2> 185719 T507 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 185720 T507 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 185720 T507 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 185721 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 185722 T507 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 185722 T507 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 185723 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 185723 T507 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 185724 T507 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 185741 T507 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 185741 T507 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 185742 T507 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 185743 T507 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44824/solr
[junit4] 2> 185743 T507 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 185744 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 185753 T547 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b081032 name:ZooKeeperConnection Watcher:127.0.0.1:44824 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 185753 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 185794 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 185797 T549 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72402ecb name:ZooKeeperConnection Watcher:127.0.0.1:44824/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 185797 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 185822 T507 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 186826 T507 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15671_pjsa
[junit4] 2> 186832 T507 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15671_pjsa
[junit4] 2> 186838 T529 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 186838 T549 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 186838 T536 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 186878 T550 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 186878 T550 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 186884 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 186884 T550 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 186885 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 186885 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 186886 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 186887 T530 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:15671/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:15671_pjsa",
[junit4] 2> "shard":null,
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"2",
[junit4] 2> "core_node_name":null}
[junit4] 2> 186888 T530 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2]
[junit4] 2> 186888 T530 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 186951 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 186968 T549 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> 186968 T536 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> 186968 T529 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> 187886 T550 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 187886 T550 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/collection1
[junit4] 2> 187887 T550 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 187888 T550 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 187888 T550 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 187889 T550 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/collection1/'
[junit4] 2> 187891 T550 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/collection1/lib/README' to classloader
[junit4] 2> 187891 T550 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/collection1/lib/classes/' to classloader
[junit4] 2> 187954 T550 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 188016 T550 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 188118 T550 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 188129 T550 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 188680 T550 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 188683 T550 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 188685 T550 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 188689 T550 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 188712 T550 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 188713 T550 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.cloud.ShardSplitTest-jetty1-1385264645750/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty1/
[junit4] 2> 188713 T550 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@18793536
[junit4] 2> 188714 T550 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty1
[junit4] 2> 188714 T550 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty1/index/
[junit4] 2> 188714 T550 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty1/index' doesn't exist. Creating new index...
[junit4] 2> 188715 T550 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty1/index
[junit4] 2> 188715 T550 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=44, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 188716 T550 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6eccec5f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@625e068),segFN=segments_1,generation=1}
[junit4] 2> 188716 T550 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 188720 T550 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 188721 T550 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 188721 T550 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 188721 T550 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 188722 T550 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 188722 T550 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 188722 T550 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 188723 T550 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 188723 T550 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 188724 T550 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 188724 T550 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 188724 T550 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 188725 T550 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 188725 T550 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 188726 T550 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 188726 T550 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 188733 T550 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 188741 T550 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 188741 T550 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 188742 T550 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=23, maxMergedSegmentMB=7.1552734375, floorSegmentMB=0.8935546875, forceMergeDeletesPctAllowed=20.14914291271336, segmentsPerTier=47.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.586977028415173
[junit4] 2> 188742 T550 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@6eccec5f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@625e068),segFN=segments_1,generation=1}
[junit4] 2> 188743 T550 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 188743 T550 oass.SolrIndexSearcher.<init> Opening Searcher@66be9fc1 main
[junit4] 2> 188746 T551 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@66be9fc1 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 188749 T550 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 188749 T550 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:15671/pjsa collection:collection1 shard:shard1
[junit4] 2> 188750 T550 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 188788 T550 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 188791 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 188791 T550 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 188791 T550 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C55 name=collection1 org.apache.solr.core.SolrCore@371eaf4e url=http://127.0.0.1:15671/pjsa/collection1 node=127.0.0.1:15671_pjsa C55_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:15671/pjsa, core=collection1, node_name=127.0.0.1:15671_pjsa}
[junit4] 2> 188792 T550 C55 P15671 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:15671/pjsa/collection1/
[junit4] 2> 188792 T550 C55 P15671 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 188792 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 188792 T550 C55 P15671 oasc.SyncStrategy.syncToMe http://127.0.0.1:15671/pjsa/collection1/ has no replicas
[junit4] 2> 188793 T550 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:15671/pjsa/collection1/ shard1
[junit4] 2> 188793 T550 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 188807 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 188825 T549 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> 188825 T536 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> 188825 T529 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> 188892 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 188910 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 189013 T529 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> 189013 T536 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> 189013 T549 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> 189045 T550 oasc.ZkController.register We are http://127.0.0.1:15671/pjsa/collection1/ and leader is http://127.0.0.1:15671/pjsa/collection1/
[junit4] 2> 189045 T550 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15671/pjsa
[junit4] 2> 189045 T550 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 189045 T550 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 189045 T550 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 189047 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 189047 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 189047 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 189047 T550 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 189051 T507 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4] 2> 189052 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 189052 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 189053 T530 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:15671/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:15671_pjsa",
[junit4] 2> "shard":"shard1",
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"2",
[junit4] 2> "core_node_name":"core_node1"}
[junit4] 2> 189069 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 189172 T549 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> 189172 T536 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> 189172 T529 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> 189363 T507 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 189366 T507 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:53902
[junit4] 2> 189367 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 189367 T507 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 189368 T507 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553
[junit4] 2> 189368 T507 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/'
[junit4] 2> 189407 T507 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/solr.xml
[junit4] 2> 189483 T507 oasc.CoreContainer.<init> New CoreContainer 748265909
[junit4] 2> 189484 T507 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/]
[junit4] 2> 189486 T507 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 189486 T507 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 189487 T507 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 189488 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 189488 T507 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 189489 T507 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 189489 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 189490 T507 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 189490 T507 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 189509 T507 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 189510 T507 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 189510 T507 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 189511 T507 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44824/solr
[junit4] 2> 189512 T507 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 189513 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 189519 T563 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a4788f3 name:ZooKeeperConnection Watcher:127.0.0.1:44824 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 189520 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 189536 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 189538 T565 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3560721e name:ZooKeeperConnection Watcher:127.0.0.1:44824/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 189538 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 189554 T507 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 190558 T507 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53902_pjsa
[junit4] 2> 190566 T507 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53902_pjsa
[junit4] 2> 190573 T549 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 190573 T565 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 190573 T529 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 190573 T536 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4] 2> 190600 T566 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 190600 T566 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 190602 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 190602 T566 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 190602 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 190603 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 190604 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 190605 T530 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:53902/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:53902_pjsa",
[junit4] 2> "shard":null,
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"2",
[junit4] 2> "core_node_name":null}
[junit4] 2> 190605 T530 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 190606 T530 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 190621 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 190726 T529 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> 190726 T549 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> 190726 T536 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> 190726 T565 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> 191604 T566 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 191604 T566 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/collection1
[junit4] 2> 191605 T566 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 191606 T566 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 191606 T566 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 191607 T566 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/collection1/'
[junit4] 2> 191609 T566 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/collection1/lib/classes/' to classloader
[junit4] 2> 191609 T566 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/collection1/lib/README' to classloader
[junit4] 2> 191676 T566 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 191739 T566 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 191841 T566 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 191852 T566 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 192430 T566 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 192434 T566 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 192437 T566 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 192442 T566 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 192473 T566 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 192474 T566 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.cloud.ShardSplitTest-jetty2-1385264649553/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty2/
[junit4] 2> 192474 T566 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@18793536
[junit4] 2> 192475 T566 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty2
[junit4] 2> 192475 T566 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty2/index/
[junit4] 2> 192476 T566 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty2/index' doesn't exist. Creating new index...
[junit4] 2> 192477 T566 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty2/index
[junit4] 2> 192477 T566 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=44, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 192478 T566 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@30f3c90f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@48719726),segFN=segments_1,generation=1}
[junit4] 2> 192479 T566 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 192485 T566 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 192485 T566 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 192486 T566 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 192486 T566 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 192487 T566 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 192487 T566 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 192487 T566 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 192488 T566 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 192488 T566 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 192489 T566 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 192490 T566 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 192490 T566 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 192491 T566 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 192492 T566 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 192492 T566 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 192493 T566 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 192503 T566 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 192509 T566 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 192509 T566 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 192510 T566 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=23, maxMergedSegmentMB=7.1552734375, floorSegmentMB=0.8935546875, forceMergeDeletesPctAllowed=20.14914291271336, segmentsPerTier=47.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.586977028415173
[junit4] 2> 192511 T566 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@30f3c90f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@48719726),segFN=segments_1,generation=1}
[junit4] 2> 192511 T566 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 192512 T566 oass.SolrIndexSearcher.<init> Opening Searcher@15eae6fb main
[junit4] 2> 192518 T567 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15eae6fb main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 192521 T566 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 192521 T566 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53902/pjsa collection:collection1 shard:shard2
[junit4] 2> 192523 T566 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 192547 T566 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4] 2> 192563 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192564 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192564 T566 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 192564 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192564 T566 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C56 name=collection1 org.apache.solr.core.SolrCore@480ae510 url=http://127.0.0.1:53902/pjsa/collection1 node=127.0.0.1:53902_pjsa C56_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:53902/pjsa, core=collection1, node_name=127.0.0.1:53902_pjsa}
[junit4] 2> 192565 T566 C56 P53902 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53902/pjsa/collection1/
[junit4] 2> 192565 T566 C56 P53902 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 192566 T566 C56 P53902 oasc.SyncStrategy.syncToMe http://127.0.0.1:53902/pjsa/collection1/ has no replicas
[junit4] 2> 192566 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 192566 T566 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53902/pjsa/collection1/ shard2
[junit4] 2> 192567 T566 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 192584 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192597 T549 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> 192597 T536 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> 192597 T565 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> 192597 T529 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> 192610 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 192629 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192732 T549 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> 192732 T565 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> 192732 T529 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> 192732 T536 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> 192761 T566 oasc.ZkController.register We are http://127.0.0.1:53902/pjsa/collection1/ and leader is http://127.0.0.1:53902/pjsa/collection1/
[junit4] 2> 192761 T566 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53902/pjsa
[junit4] 2> 192761 T566 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 192762 T566 oasc.ZkController.publish publishing core=collection1 state=active
[junit4] 2> 192762 T566 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 192764 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192764 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192764 T566 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 192764 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192766 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 192766 T507 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4] 2> 192767 T530 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:53902/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:53902_pjsa",
[junit4] 2> "shard":"shard2",
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"2",
[junit4] 2> "core_node_name":"core_node2"}
[junit4] 2> 192767 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 192789 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 192893 T549 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> 192893 T565 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> 192893 T536 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> 192893 T529 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> 193053 T507 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 193056 T507 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58589
[junit4] 2> 193057 T507 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 193058 T507 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 193058 T507 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272
[junit4] 2> 193059 T507 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/'
[junit4] 2> 193096 T507 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/solr.xml
[junit4] 2> 193172 T507 oasc.CoreContainer.<init> New CoreContainer 1797695708
[junit4] 2> 193173 T507 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/]
[junit4] 2> 193175 T507 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 193175 T507 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4] 2> 193176 T507 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 193176 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 193177 T507 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 193177 T507 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 193178 T507 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 193178 T507 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 193179 T507 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 193198 T507 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 193198 T507 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 193199 T507 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 193199 T507 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:44824/solr
[junit4] 2> 193200 T507 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 193201 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 193204 T579 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37183a79 name:ZooKeeperConnection Watcher:127.0.0.1:44824 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 193204 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 193211 T507 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 193214 T581 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a5b784b name:ZooKeeperConnection Watcher:127.0.0.1:44824/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 193214 T507 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 193233 T507 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 194236 T507 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58589_pjsa
[junit4] 2> 194238 T507 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58589_pjsa
[junit4] 2> 194242 T549 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 194243 T565 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 194243 T581 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 194242 T536 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 194242 T529 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4] 2> 194262 T582 oasc.ZkController.publish publishing core=collection1 state=down
[junit4] 2> 194263 T582 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 194267 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 194267 T582 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 194267 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 194268 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 194269 T530 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 194270 T530 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:58589/pjsa",
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "node_name":"127.0.0.1:58589_pjsa",
[junit4] 2> "shard":null,
[junit4] 2> "shard_range":null,
[junit4] 2> "shard_state":"active",
[junit4] 2> "shard_parent":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"2",
[junit4] 2> "core_node_name":null}
[junit4] 2> 194270 T530 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 194271 T530 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 194274 T529 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 194378 T549 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 194378 T581 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 194378 T565 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 194378 T536 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 194378 T529 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4] 2> 195269 T582 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 195269 T582 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: ./org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/collection1
[junit4] 2> 195270 T582 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 195271 T582 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 195271 T582 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 195272 T582 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/collection1/'
[junit4] 2> 195273 T582 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/collection1/lib/README' to classloader
[junit4] 2> 195274 T582 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/collection1/lib/classes/' to classloader
[junit4] 2> 195337 T582 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_47
[junit4] 2> 195398 T582 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 195500 T582 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 195515 T582 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 196094 T582 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 196099 T582 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 196101 T582 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 196107 T582 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 196136 T582 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 196137 T582 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./org.apache.solr.cloud.ShardSplitTest-jetty3-1385264653272/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty3/
[junit4] 2> 196137 T582 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@18793536
[junit4] 2> 196138 T582 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty3
[junit4] 2> 196138 T582 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty3/index/
[junit4] 2> 196138 T582 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty3/index' doesn't exist. Creating new index...
[junit4] 2> 196139 T582 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty3/index
[junit4] 2> 196139 T582 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=44, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 196140 T582 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@43c83579 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@45590b70),segFN=segments_1,generation=1}
[junit4] 2> 196140 T582 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 196144 T582 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
[junit4] 2> 196144 T582 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
[junit4] 2> 196145 T582 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4] 2> 196145 T582 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
[junit4] 2> 196145 T582 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4] 2> 196145 T582 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
[junit4] 2> 196146 T582 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 196146 T582 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4] 2> 196146 T582 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 196147 T582 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 196148 T582 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 196148 T582 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 196148 T582 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 196149 T582 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 196149 T582 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4] 2> 196150 T582 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
[junit4] 2> 196156 T582 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 196160 T582 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 196160 T582 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 196161 T582 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=32, maxMergeAtOnceExplicit=23, maxMergedSegmentMB=7.1552734375, floorSegmentMB=0.8935546875, forceMergeDeletesPctAllowed=20.14914291271336, segmentsPerTier=47.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.586977028415173
[junit4] 2> 196161 T582 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(org.apache.lucene.store.RAMDirectory@43c83579 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@45590b70),segFN=segments_1,generation=1}
[junit4] 2> 196162 T582 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 196162 T582 oass.SolrIndexSearcher.<init> Opening Searcher@4a96e8fb main
[junit4] 2> 196165 T583 oasc.SolrCore.registerSearcher [collection1] Registered
[...truncated too long message...]
t to sync replicas back to leader
[junit4] 2> 398593 T598 oasc.ShardLeaderElectionContext.runLeaderProcess Sync was not a success but no one else is active! I am the leader
[junit4] 2> 398593 T598 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:27175/pjsa/collection1/ shard2
[junit4] 2> 398593 T598 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@7a4b443a
[junit4] 2> 398607 T598 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=824,cumulative_deletesById=395,cumulative_deletesByQuery=1,cumulative_errors=0,transaction_logs_total_size=0,transaction_logs_total_number=1}
[junit4] 2> 398607 T598 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 398607 T598 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 398608 T598 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 398609 T598 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 398610 T598 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 398610 T598 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty4/index;done=false>>]
[junit4] 2> 398610 T598 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty4/index
[junit4] 2> 398610 T598 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty4;done=false>>]
[junit4] 2> 398611 T598 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1385264642559/jetty4
[junit4] 2> 398611 T598 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 398612 T598 oasc.SolrException.log ERROR There was a problem trying to register as the leader:org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections
[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.exists(ZooKeeper.java:1041)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:201)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:409)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:266)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 398612 T598 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/90784703615336460-core_node4-n_0000000001
[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.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:169)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:166)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:166)
[junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:66)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:269)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 398613 T598 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 398613 T598 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> 398613 T598 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 398614 T598 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[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.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> NOTE: test params are: codec=Appending, sim=DefaultSimilarity, locale=cs_CZ, timezone=America/Panama
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=275664544,total=460259328
[junit4] 2> NOTE: All tests run in this JVM: [UpdateParamsTest, DeleteReplicaTest, OverseerCollectionProcessorTest, ZkCLITest, UnloadDistributedZkTest, TestLMJelinekMercerSimilarityFactory, TestImplicitCoreProperties, TestShardHandlerFactory, BasicFunctionalityTest, CSVRequestHandlerTest, TestSolrXMLSerializer, TermVectorComponentTest, PrimitiveFieldTypeTest, RegexBoostProcessorTest, ClusterStateTest, ShardSplitTest]
[junit4] Completed on J0 in 217.04s, 1 test, 1 failure <<< FAILURES!
[...truncated 954 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:426: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:406: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:492: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1276: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:912: There were test failures: 345 suites, 1505 tests, 1 failure, 35 ignored (7 assumptions)
Total time: 65 minutes 55 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 2188 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/2188/
1 tests failed.
REGRESSION: org.apache.solr.cloud.OverseerTest.testOverseerFailure
Error Message:
KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
Stack Trace:
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
at __randomizedtesting.SeedInfo.seed([A509AA2453043997:A10125D741A1D6B6]:0)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:424)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:421)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:157)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:679)
Build Log:
[...truncated 9874 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> 1195082 T2206 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-OverseerTest-1385310296022
[junit4] 2> 1195083 T2206 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 1195087 T2206 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 1195088 T2206 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1195088 T2207 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1195189 T2206 oasc.ZkTestServer.run start zk server on port:12858
[junit4] 2> 1195190 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1195193 T2213 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9ad50d9 name:ZooKeeperConnection Watcher:127.0.0.1:12858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1195194 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1195195 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1195196 T2215 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51743cd1 name:ZooKeeperConnection Watcher:127.0.0.1:12858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1195197 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1195208 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1195210 T2217 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b531475 name:ZooKeeperConnection Watcher:127.0.0.1:12858 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1195210 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1195210 T2206 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1195215 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1195224 T2206 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1195226 T2206 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1195228 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1195231 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1195233 T2219 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5eddb023 name:ZooKeeperConnection Watcher:127.0.0.1:12858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1195233 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1195234 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1195236 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1195239 T2213 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1195239 T2219 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1195239 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1195241 T2221 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@412a59d2 name:ZooKeeperConnection Watcher:127.0.0.1:12858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1195241 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1195242 T2206 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1195253 T2206 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1195255 T2206 oasc.Overseer.start Overseer (id=90787695560818692-127.0.0.1:12858_solr-n_0000000000) starting
[junit4] 2> 1195257 T2206 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1195260 T2206 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1195264 T2206 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1195266 T2223 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1195267 T2222 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1196269 T2221 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1196271 T2222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1196271 T2222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1196272 T2222 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 1196272 T2222 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1196281 T2221 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1196282 T2219 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> 1196282 T2213 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> 1196770 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1196789 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1196794 T2221 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1196795 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1196796 T2222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1196798 T2221 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1196798 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1196800 T2222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1196800 T2222 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1196803 T2221 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1196905 T2213 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> 1196905 T2219 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> 1197960 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1197976 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1197978 T2225 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3e8e8d8f name:ZooKeeperConnection Watcher:127.0.0.1:12858/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1197978 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1197981 T2206 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1197983 T2206 oasc.Overseer.start Overseer (id=90787695560818693-127.0.0.1:12858_solr-n_0000000001) starting
[junit4] 2> 1197988 T2227 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1197988 T2226 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1197990 T2226 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1197991 T2226 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1197991 T2226 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1197994 T2225 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1197995 T2219 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> 1197995 T2213 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> 1198048 T2225 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1198048 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1198049 T2226 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1198060 T2206 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/90787695560818691-node1_core1-n_0000000002
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:111)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1151)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:269)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:126)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
[junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4] 2> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] 2> at java.lang.reflect.Method.invoke(Method.java:616)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4] 2> at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4] 2> at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4] 2> at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4] 2> at java.lang.Thread.run(Thread.java:679)
[junit4] 2>
[junit4] 2> 1198062 T2219 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1198063 T2226 oasc.SolrException.log ERROR Problem cleaning up collection in zk:collection1:org.apache.zookeeper.KeeperException$NotEmptyException: KeeperErrorCode = Directory not empty for /collections/collection1/leader_elect/shard1/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:125)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:169)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:166)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:166)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:650)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:645)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:645)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:645)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:875)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:224)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:185)
[junit4] 2> at java.lang.Thread.run(Thread.java:679)
[junit4] 2>
[junit4] 2> 1198063 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1198066 T2225 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1198068 T2225 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1198069 T2213 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1198070 T2226 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 1198073 T2206 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:12858 12858
[junit4] 2> 1198140 T2206 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=A509AA2453043997 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_SV -Dtests.timezone=CST6CDT -Dtests.file.encoding=US-ASCII
[junit4] ERROR 3.08s J0 | OverseerTest.testOverseerFailure <<<
[junit4] > Throwable #1: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at __randomizedtesting.SeedInfo.seed([A509AA2453043997:A10125D741A1D6B6]:0)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] > at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:424)
[junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:421)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] > at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:157)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
[junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
[junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
[junit4] > at java.lang.Thread.run(Thread.java:679)
[junit4] 2> 1198165 T2206 oas.SolrTestCaseJ4.setUp ###Starting testStateChange
[junit4] 2> 1198165 T2206 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1198166 T2228 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1198267 T2206 oasc.ZkTestServer.run start zk server on port:27049
[junit4] 2> 1198268 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1198271 T2234 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@742d87c name:ZooKeeperConnection Watcher:127.0.0.1:27049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1198271 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1198272 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1198274 T2236 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59ab08a4 name:ZooKeeperConnection Watcher:127.0.0.1:27049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1198274 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1198329 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1198330 T2238 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7446115c name:ZooKeeperConnection Watcher:127.0.0.1:27049 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1198330 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1198331 T2206 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1198334 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1198336 T2206 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1198338 T2206 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1198340 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1198342 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1198344 T2240 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5d8a1a9e name:ZooKeeperConnection Watcher:127.0.0.1:27049/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1198344 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1198345 T2206 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1198350 T2206 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1198352 T2206 oasc.Overseer.start Overseer (id=90787695762669571-127.0.0.1:27049_solr-n_0000000000) starting
[junit4] 2> 1198355 T2206 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1198358 T2206 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1198361 T2206 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1198364 T2242 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1198364 T2241 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1198366 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1198366 T2241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1198367 T2241 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 1198367 T2241 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1198370 T2240 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1198370 T2234 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1198418 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1198420 T2240 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1198421 T2241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1198422 T2241 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"active"}
[junit4] 2> 1198422 T2241 oasc.Overseer$ClusterStateUpdater.updateState node=core_node1 is already registered
[junit4] 2> 1198422 T2241 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1198431 T2240 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1198534 T2234 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1198576 T2206 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:27049 27049
[junit4] 2> 1199570 T2219 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1199830 T2219 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections
[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.exists(ZooKeeper.java:1041)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:201)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:409)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1199831 T2206 oas.SolrTestCaseJ4.tearDown ###Ending testStateChange
[junit4] 2> 1199832 T2219 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1199837 T2206 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
[junit4] 2> 1199838 T2206 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1199838 T2243 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1199939 T2206 oasc.ZkTestServer.run start zk server on port:20331
[junit4] 2> 1199940 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1199944 T2249 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e22370e name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1199944 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1199945 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1199953 T2251 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1926b4dc name:ZooKeeperConnection Watcher:127.0.0.1:20331 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1199954 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1199968 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1199970 T2253 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6500913d name:ZooKeeperConnection Watcher:127.0.0.1:20331 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1199970 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1199970 T2206 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1199973 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1199977 T2254 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1199977 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1199978 T2256 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@54d6740 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1199978 T2254 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1199978 T2258 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cb59d78 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1199979 T2254 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1199979 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1199980 T2206 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1199982 T2206 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1199983 T2254 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1199984 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1199984 T2254 oasc.Overseer.start Overseer (id=90787695872114691-127.0.0.1:20331_solr-n_0000000000) starting
[junit4] 2> 1199986 T2254 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1199987 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1199989 T2254 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1199989 T2258 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1199992 T2254 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1199993 T2260 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1199993 T2254 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 1199995 T2254 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1199996 T2262 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@520294f9 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1199996 T2254 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1199999 T2254 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1200001 T2254 oasc.Overseer.start Overseer (id=90787695872114693-127.0.0.1:20331_solr-n_0000000001) starting
[junit4] 2> 1200005 T2264 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1200005 T2263 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1200007 T2263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1200008 T2263 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1200008 T2263 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 1200008 T2263 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1200010 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200011 T2258 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> 1200492 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1200523 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1200529 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200531 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200531 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1200531 T2263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1200535 T2263 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1200536 T2263 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1200536 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1200538 T2266 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a2c3910 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1200538 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1200539 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200540 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1200542 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 1200544 T2258 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1200544 T2266 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1200546 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200547 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1200547 T2263 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1200548 T2263 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1200550 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200552 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1200653 T2258 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> 1200653 T2266 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> 1200654 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1200665 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200665 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200675 T2263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1200676 T2263 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"}
[junit4] 2> 1200676 T2263 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4] 2> 1200676 T2263 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1200679 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1200781 T2258 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> 1200781 T2266 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> 1201166 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201183 T2266 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201183 T2258 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201184 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201184 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1201189 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201189 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201189 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201190 T2263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201193 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201286 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201296 T2266 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> 1201388 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201390 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1201392 T2268 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3afea8d0 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1201392 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1201393 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1201396 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1201398 T2266 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201398 T2268 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201409 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201409 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201409 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201409 T2262 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201411 T2263 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201411 T2263 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201412 T2263 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201419 T2254 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 1201422 T2254 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1201424 T2270 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6905191c name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1201425 T2266 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201425 T2254 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1201425 T2268 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201427 T2268 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1201428 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201428 T2254 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1201431 T2254 oasc.Overseer.start Overseer (id=90787695872114696-127.0.0.1:20331_solr-n_0000000002) starting
[junit4] 2> 1201451 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1201453 T2274 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1201453 T2273 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65e86845 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1201453 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1201455 T2271 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201455 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1201455 T2271 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 1201456 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201456 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201457 T2273 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> 1201457 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 1201457 T2268 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> 1201459 T2271 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1201460 T2268 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201460 T2273 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201461 T2271 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201462 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201462 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201462 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201462 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201466 T2273 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> 1201466 T2268 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> 1201469 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201470 T2271 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201470 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201470 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201473 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201476 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201476 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201477 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201479 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201495 T2260 oasc.OverseerCollectionProcessor.amILeader 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:1151)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:269)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.amILeader(OverseerCollectionProcessor.java:203)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:162)
[junit4] 2> at java.lang.Thread.run(Thread.java:679)
[junit4] 2>
[junit4] 2> 1201495 T2259 oasc.Overseer$ClusterStateUpdater.run WARN Solr cannot talk to ZK, exiting Overseer work queue loop org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue-work
[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.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.orderedChildren(DistributedQueue.java:89)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.element(DistributedQueue.java:131)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:325)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:103)
[junit4] 2> at java.lang.Thread.run(Thread.java:679)
[junit4] 2>
[junit4] 2> 1201495 T2260 oasc.OverseerCollectionProcessor.amILeader According to ZK I (id=90787695872114691-127.0.0.1:20331_solr-n_0000000000) am no longer a leader.
[junit4] 2> 1201571 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201581 T2273 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> 1201581 T2268 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> 1201673 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201676 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201676 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201676 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201677 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201678 T2271 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201678 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"}
[junit4] 2> 1201679 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201695 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201696 T2273 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201696 T2268 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201697 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201698 T2273 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1201702 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201705 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201799 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201808 T2273 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> 1201901 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201903 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1201905 T2276 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48d66f1f name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1201905 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1201906 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1201908 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1201911 T2273 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201911 T2276 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201921 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201921 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201922 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201922 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201923 T2271 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201924 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201924 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201936 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201937 T2276 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201937 T2273 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1201939 T2276 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1201940 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201940 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201941 T2271 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201941 T2271 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201944 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201947 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1201948 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201949 T2278 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7233533a name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1201949 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1201951 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1201953 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 1201955 T2276 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201955 T2278 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1201957 T2254 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 1201957 T2270 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201957 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1201958 T2254 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1201960 T2280 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@430d802b name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1201960 T2254 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1201963 T2254 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1201963 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201965 T2254 oasc.Overseer.start Overseer (id=90787695872114700-127.0.0.1:20331_solr-n_0000000003) starting
[junit4] 2> 1201970 T2282 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1201971 T2281 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201971 T2281 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 1201972 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201972 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201973 T2278 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> 1201973 T2276 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> 1201976 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201976 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201977 T2278 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> 1201977 T2276 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> 1201981 T2278 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> 1201981 T2276 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> 1201983 T2281 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1201984 T2281 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1201985 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1201985 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1201987 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1201988 T2278 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> 1201988 T2276 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> 1202065 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202068 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202069 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1202070 T2281 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202071 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"}
[junit4] 2> 1202071 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202080 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202082 T2278 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1202082 T2276 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1202083 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202084 T2278 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1202088 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202091 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202185 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202193 T2278 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> 1202287 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202289 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1202290 T2284 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7339ea2c name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1202291 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1202292 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1202294 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1202297 T2278 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1202297 T2284 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1202306 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202306 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1202306 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202307 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202308 T2281 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202309 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1202309 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202321 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202323 T2284 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1202323 T2278 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1202325 T2284 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1202326 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202326 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1202327 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1202327 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202330 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202333 T2206 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1202334 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202334 T2286 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6209f0f2 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1202335 T2206 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1202336 T2206 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1202338 T2206 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 1202340 T2284 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1202341 T2286 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1202342 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202343 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1202343 T2281 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1202344 T2281 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202346 T2280 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202348 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202373 T2254 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 1202374 T2254 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1202376 T2288 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ac63ad8 name:ZooKeeperConnection Watcher:127.0.0.1:20331/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1202376 T2254 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1202379 T2254 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1202381 T2254 oasc.Overseer.start Overseer (id=90787695872114703-127.0.0.1:20331_solr-n_0000000004) starting
[junit4] 2> 1202385 T2290 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1202387 T2289 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202387 T2289 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 1202388 T2289 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1202388 T2289 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202389 T2286 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> 1202389 T2284 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> 1202391 T2289 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1202391 T2289 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202392 T2284 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> 1202392 T2286 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> 1202396 T2286 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> 1202396 T2284 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> 1202398 T2289 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1202398 T2289 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1202399 T2284 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> 1202399 T2286 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> 1202401 T2289 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1202448 T2281 oasc.Overseer$ClusterStateUpdater.run WARN Solr cannot talk to ZK, exiting Overseer main queue loop org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer/queue
[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.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.orderedChildren(DistributedQueue.java:89)
[junit4] 2> at org.apache.solr.cloud.DistributedQueue.peek(DistributedQueue.java:411)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:193)
[junit4] 2> at java.lang.Thread.run(Thread.java:679)
[junit4] 2>
[junit4] 2> 1202449 T2206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202452 T2288 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1202452 T2206 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1202453 T2289 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1202454 T2289 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"}
[...truncated too long message...]
n.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1220575 T2583 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard11/election/90787696780050504-node68_core68-n_0000000002
[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:1151)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:269)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:126)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1220575 T2583 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1220579 T2585 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1220596 T2599 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1220604 T2605 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard9
[junit4] 2> 1220604 T2605 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections
[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.exists(ZooKeeper.java:1041)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:201)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:409)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1220604 T2605 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1220607 T2607 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leaders/shard15
[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.create(ZooKeeper.java:783)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:424)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:421)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1220607 T2607 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1222177 T2206 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene42, sim=DefaultSimilarity, locale=es_SV, timezone=CST6CDT
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=229364304,total=430112768
[junit4] 2> NOTE: All tests run in this JVM: [TestUniqueKeyFieldResource, TestReversedWildcardFilterFactory, TestSort, ResponseLogComponentTest, HdfsDirectoryTest, BinaryUpdateRequestHandlerTest, PolyFieldTest, AnalysisAfterCoreReloadTest, TestLuceneMatchVersion, TestNRTOpen, HdfsBasicDistributedZkTest, TestRealTimeGet, TestSolrXMLSerializer, RegexBoostProcessorTest, TestBadConfig, HdfsUnloadDistributedZkTest, TestFaceting, TestSearchPerf, SampleTest, TestFieldResource, RecoveryZkTest, TestSolrIndexConfig, HdfsRecoveryZkTest, MoreLikeThisHandlerTest, BasicDistributedZkTest, DateMathParserTest, DistributedTermsComponentTest, StressHdfsTest, ZkControllerTest, TestRecoveryHdfs, TestValueSourceCache, TestConfig, TestSolrQueryParser, TestSolrQueryParserResource, LoggingHandlerTest, TestManagedSchema, BasicFunctionalityTest, TestPseudoReturnFields, ShardSplitTest, IndexSchemaTest, StatelessScriptUpdateProcessorFactoryTest, TestQueryUtils, JsonLoaderTest, TestNoOpRegenerator, TestSolrDeletionPolicy1, TestLFUCache, TestModifyConfFiles, BlockDirectoryTest, SpellPossibilityIteratorTest, SolrInfoMBeanTest, SynonymTokenizerTest, CSVRequestHandlerTest, OverseerCollectionProcessorTest, LegacyHTMLStripCharFilterTest, SoftAutoCommitTest, TestPHPSerializedResponseWriter, TestRandomDVFaceting, UpdateRequestProcessorFactoryTest, SliceStateTest, TestCollationKeyRangeQueries, CacheHeaderTest, PrimitiveFieldTypeTest, URLClassifyProcessorTest, ReturnFieldsTest, DocumentBuilderTest, TestDocSet, TestLMDirichletSimilarityFactory, QueryParsingTest, ClusterStateUpdateTest, CachingDirectoryFactoryTest, CoreAdminHandlerTest, FileBasedSpellCheckerTest, ScriptEngineTest, UnloadDistributedZkTest, ParsingFieldUpdateProcessorsTest, TestSimpleQParserPlugin, TestCharFilters, TestWriterPerf, TestMaxScoreQueryParser, EnumFieldTest, DocValuesTest, CoreMergeIndexesAdminHandlerTest, ExternalFileFieldSortTest, BasicDistributedZk2Test, OverseerTest]
[junit4] Completed on J0 in 27.13s, 8 tests, 1 error <<< FAILURES!
[...truncated 532 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:426: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:406: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:492: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1279: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:912: There were test failures: 345 suites, 1505 tests, 1 error, 35 ignored (7 assumptions)
Total time: 65 minutes 2 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure