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 2014/08/07 00:12:34 UTC

[JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 592 - Still Failing

Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/592/

2 tests failed.
REGRESSION:  org.apache.solr.cloud.CollectionsAPIDistributedZkTest.testDistribSearch

Error Message:
Captured an uncaught exception in thread: Thread[id=780113, name=RecoveryThread, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]

Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=780113, name=RecoveryThread, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
Caused by: java.lang.OutOfMemoryError: unable to create new native thread
	at __randomizedtesting.SeedInfo.seed([AB9A8892F2A68BB5]:0)
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:949)
	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1360)
	at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:132)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.httpUriRequest(HttpSolrServer.java:241)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.httpUriRequest(HttpSolrServer.java:230)
	at org.apache.solr.cloud.RecoveryStrategy.sendPrepRecoveryCmd(RecoveryStrategy.java:610)
	at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:371)
	at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:235)


FAILED:  org.apache.solr.cloud.MultiThreadedOCPTest.testDistribSearch

Error Message:
We have a failed SPLITSHARD task

Stack Trace:
java.lang.AssertionError: We have a failed SPLITSHARD task
	at __randomizedtesting.SeedInfo.seed([AB9A8892F2A68BB5:2A7C068A85F9EB89]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.junit.Assert.assertTrue(Assert.java:43)
	at org.apache.solr.cloud.MultiThreadedOCPTest.testTaskExclusivity(MultiThreadedOCPTest.java:125)
	at org.apache.solr.cloud.MultiThreadedOCPTest.doTest(MultiThreadedOCPTest.java:71)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:867)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365)
	at java.lang.Thread.run(Thread.java:745)




Build Log:
[...truncated 11458 lines...]
   [junit4] Suite: org.apache.solr.cloud.MultiThreadedOCPTest
   [junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/init-core-data-001
   [junit4]   2> 230469 T2098 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (false)
   [junit4]   2> 230469 T2098 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /a/xe
   [junit4]   2> 230474 T2098 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
   [junit4]   2> 230475 T2098 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 230476 T2099 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 230576 T2098 oasc.ZkTestServer.run start zk server on port:37975
   [junit4]   2> 230578 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 230581 T2105 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17c0ae63 name:ZooKeeperConnection Watcher:127.0.0.1:37975 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 230582 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 230582 T2098 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 230585 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 230586 T2107 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@755629fd name:ZooKeeperConnection Watcher:127.0.0.1:37975/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 230586 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 230586 T2098 oascc.SolrZkClient.makePath makePath: /collections/collection1
   [junit4]   2> 230587 T2098 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
   [junit4]   2> 230589 T2098 oascc.SolrZkClient.makePath makePath: /collections/control_collection
   [junit4]   2> 230590 T2098 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
   [junit4]   2> 230591 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
   [junit4]   2> 230592 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
   [junit4]   2> 230594 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
   [junit4]   2> 230594 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
   [junit4]   2> 230596 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 230597 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 230598 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
   [junit4]   2> 230598 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
   [junit4]   2> 230600 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
   [junit4]   2> 230600 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
   [junit4]   2> 230601 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
   [junit4]   2> 230607 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
   [junit4]   2> 230608 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
   [junit4]   2> 230609 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml
   [junit4]   2> 230610 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
   [junit4]   2> 230610 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
   [junit4]   2> 230612 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 230612 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 230613 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
   [junit4]   2> 230614 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
   [junit4]   2> 230615 T2098 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
   [junit4]   2> 230615 T2098 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
   [junit4]   2> 231663 T2098 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 231667 T2098 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:13902
   [junit4]   2> 231668 T2098 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 231668 T2098 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 231668 T2098 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002
   [junit4]   2> 231669 T2098 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/'
   [junit4]   2> 231698 T2098 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/solr.xml
   [junit4]   2> 231752 T2098 oasc.CoreContainer.<init> New CoreContainer 1185402054
   [junit4]   2> 231753 T2098 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/]
   [junit4]   2> 231754 T2098 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 231754 T2098 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: 
   [junit4]   2> 231754 T2098 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 231754 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 231755 T2098 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 231755 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 231755 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 231755 T2098 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 231756 T2098 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 231756 T2098 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
   [junit4]   2> 231756 T2098 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 231757 T2098 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 231757 T2098 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 231757 T2098 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:37975/solr
   [junit4]   2> 231757 T2098 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 231758 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 231759 T2118 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3274ff67 name:ZooKeeperConnection Watcher:127.0.0.1:37975 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 231760 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 231761 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 231762 T2120 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a8e394c name:ZooKeeperConnection Watcher:127.0.0.1:37975/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 231762 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 231763 T2098 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 231765 T2098 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 231767 T2098 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
   [junit4]   2> 231769 T2098 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
   [junit4]   2> 231770 T2098 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
   [junit4]   2> 231772 T2098 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 231773 T2098 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:13902_a%2Fxe
   [junit4]   2> 231774 T2098 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:13902_a%2Fxe
   [junit4]   2> 231775 T2098 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 231777 T2098 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 231779 T2098 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:13902_a%2Fxe
   [junit4]   2> 231779 T2098 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 231781 T2098 oasc.Overseer.start Overseer (id=92232553437659139-127.0.0.1:13902_a%2Fxe-n_0000000000) starting
   [junit4]   2> 231783 T2098 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 231788 T2122 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 231788 T2098 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 231790 T2098 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 231791 T2098 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 231793 T2121 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 231798 T2123 oasc.ZkController.publish publishing core=collection1 state=down collection=control_collection
   [junit4]   2> 231799 T2123 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 231799 T2123 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 231800 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 231801 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 231801 T2121 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:13902/a/xe",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:13902_a%2Fxe",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 231801 T2121 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
   [junit4]   2> 231801 T2121 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 231803 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 231804 T2124 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> 232800 T2123 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 232801 T2123 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
   [junit4]   2> 232801 T2123 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 232802 T2123 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
   [junit4]   2> 232802 T2123 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 232803 T2123 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/collection1/'
   [junit4]   2> 232805 T2123 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/collection1/lib/.svn/' to classloader
   [junit4]   2> 232805 T2123 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/collection1/lib/README' to classloader
   [junit4]   2> 232806 T2123 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/collection1/lib/classes/' to classloader
   [junit4]   2> 232873 T2123 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10
   [junit4]   2> 232922 T2123 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 232923 T2123 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 232938 T2123 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 233394 T2123 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 233395 T2123 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 233395 T2123 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 233410 T2123 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 233413 T2123 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 233433 T2123 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 233438 T2123 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 233442 T2123 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 233443 T2123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 233443 T2123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 233443 T2123 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 233444 T2123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 233444 T2123 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 233445 T2123 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection control_collection
   [junit4]   2> 233445 T2123 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 233445 T2123 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-002/collection1/, dataDir=./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-001/control/data/
   [junit4]   2> 233445 T2123 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3f8c26ff
   [junit4]   2> 233456 T2123 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-001/control/data
   [junit4]   2> 233457 T2123 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-001/control/data/index/
   [junit4]   2> 233458 T2123 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-001/control/data/index' doesn't exist. Creating new index...
   [junit4]   2> 233458 T2123 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-001/control/data/index
   [junit4]   2> 233458 T2123 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=9, maxMergeAtOnceExplicit=5, maxMergedSegmentMB=1.2470703125, floorSegmentMB=2.1884765625, forceMergeDeletesPctAllowed=23.277766949976346, segmentsPerTier=21.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 233459 T2123 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RAMDirectory@6b88d968 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@67ea74f),segFN=segments_1,generation=1}
   [junit4]   2> 233460 T2123 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 233475 T2123 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 233475 T2123 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 233476 T2123 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 233476 T2123 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 233476 T2123 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 233476 T2123 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 233477 T2123 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 233478 T2123 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 233478 T2123 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 233478 T2123 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 233479 T2123 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 233479 T2123 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 233480 T2123 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 233480 T2123 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 233481 T2123 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 233481 T2123 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 233482 T2123 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 233482 T2123 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 233483 T2123 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 233483 T2123 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 233484 T2123 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 233503 T2123 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 233505 T2123 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 233507 T2123 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 233508 T2123 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 233510 T2123 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 233516 T2123 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 233516 T2123 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 233517 T2123 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=8, maxMergeAtOnceExplicit=6, maxMergedSegmentMB=90.3037109375, floorSegmentMB=0.8642578125, forceMergeDeletesPctAllowed=12.1405079704558, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 233518 T2123 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RAMDirectory@6b88d968 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@67ea74f),segFN=segments_1,generation=1}
   [junit4]   2> 233518 T2123 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 233519 T2123 oass.SolrIndexSearcher.<init> Opening Searcher@29423654[collection1] main
   [junit4]   2> 233519 T2123 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
   [junit4]   2> 233520 T2123 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 233520 T2123 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
   [junit4]   2> 233521 T2123 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
   [junit4]   2> 233521 T2123 oasr.RestManager.init Initializing RestManager with initArgs: {}
   [junit4]   2> 233521 T2123 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 233522 T2123 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream No data found for znode /configs/conf1/_rest_managed.json
   [junit4]   2> 233522 T2123 oasr.ManagedResourceStorage.load Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 233522 T2123 oascc.SolrZkClient.makePath makePath: /configs/conf1/_rest_managed.json
   [junit4]   2> 233524 T2123 oasr.ManagedResourceStorage$ZooKeeperStorageIO$1.close Wrote 38 bytes to new znode /configs/conf1/_rest_managed.json
   [junit4]   2> 233524 T2123 oasr.ManagedResourceStorage$JsonStorage.store Saved JSON object to path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 233525 T2123 oasr.RestManager.init Initializing 0 registered ManagedResources
   [junit4]   2> 233528 T2125 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29423654[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 233532 T2123 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 233533 T2128 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:13902/a/xe collection:control_collection shard:shard1
   [junit4]   2> 233534 T2098 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
   [junit4]   2> 233534 T2098 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 233534 T2128 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
   [junit4]   2> 233535 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 233537 T2130 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@45d5e97e name:ZooKeeperConnection Watcher:127.0.0.1:37975/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 233537 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 233538 T2098 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 233539 T2128 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 233540 T2098 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false
   [junit4]   2> 233540 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233541 T2128 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 233541 T2128 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C38 name=collection1 org.apache.solr.core.SolrCore@164bbee7 url=http://127.0.0.1:13902/a/xe/collection1 node=127.0.0.1:13902_a%2Fxe C38_STATE=coll:control_collection core:collection1 props:{state=down, base_url=http://127.0.0.1:13902/a/xe, core=collection1, node_name=127.0.0.1:13902_a%2Fxe}
   [junit4]   2> 233541 T2128 C38 P13902 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:13902/a/xe/collection1/
   [junit4]   2> 233541 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 233542 T2128 C38 P13902 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 233542 T2128 C38 P13902 oasc.SyncStrategy.syncToMe http://127.0.0.1:13902/a/xe/collection1/ has no replicas
   [junit4]   2> 233542 T2128 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:13902/a/xe/collection1/ shard1
   [junit4]   2> 233543 T2128 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
   [junit4]   2> 233544 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233544 T2124 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> 233544 T2131 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> 233546 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233547 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 233549 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233650 T2131 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> 233650 T2124 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> 233699 T2128 oasc.ZkController.register We are http://127.0.0.1:13902/a/xe/collection1/ and leader is http://127.0.0.1:13902/a/xe/collection1/
   [junit4]   2> 233700 T2128 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:13902/a/xe
   [junit4]   2> 233700 T2128 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 233700 T2128 oasc.ZkController.publish publishing core=collection1 state=active collection=control_collection
   [junit4]   2> 233700 T2128 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 233702 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233702 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233702 T2128 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 233702 T2133 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233703 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 233703 T2121 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:13902/a/xe",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:13902_a%2Fxe",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":"core_node1"}
   [junit4]   2> 233705 T2133 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 233807 T2133 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> 233807 T2131 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> 234645 T2098 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 1
   [junit4]   2> 234645 T2098 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 234648 T2098 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:33669
   [junit4]   2> 234648 T2098 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 234649 T2098 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 234649 T2098 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003
   [junit4]   2> 234649 T2098 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/'
   [junit4]   2> 234679 T2098 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/solr.xml
   [junit4]   2> 234733 T2098 oasc.CoreContainer.<init> New CoreContainer 322531860
   [junit4]   2> 234734 T2098 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/]
   [junit4]   2> 234735 T2098 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 234735 T2098 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: 
   [junit4]   2> 234735 T2098 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 234735 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 234735 T2098 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 234736 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 234736 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 234736 T2098 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 234736 T2098 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 234737 T2098 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
   [junit4]   2> 234737 T2098 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 234737 T2098 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 234738 T2098 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 234738 T2098 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:37975/solr
   [junit4]   2> 234738 T2098 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 234739 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 234740 T2144 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@207088e8 name:ZooKeeperConnection Watcher:127.0.0.1:37975 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 234741 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 234743 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 234744 T2146 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20d7aa52 name:ZooKeeperConnection Watcher:127.0.0.1:37975/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 234744 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 234748 T2098 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 235751 T2098 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33669_a%2Fxe
   [junit4]   2> 235752 T2098 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33669_a%2Fxe
   [junit4]   2> 235754 T2133 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 235754 T2147 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 235754 T2131 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 235761 T2148 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
   [junit4]   2> 235761 T2148 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 235762 T2133 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 235762 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 235762 T2148 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 235762 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 235763 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 235764 T2121 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:33669/a/xe",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:33669_a%2Fxe",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 235764 T2121 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2]
   [junit4]   2> 235764 T2121 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 235766 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 235766 T2131 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> 235766 T2147 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> 235766 T2132 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> 236763 T2148 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 236764 T2148 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 236764 T2148 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 236764 T2148 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 236765 T2148 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 236765 T2148 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/'
   [junit4]   2> 236767 T2148 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/lib/README' to classloader
   [junit4]   2> 236768 T2148 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/lib/.svn/' to classloader
   [junit4]   2> 236769 T2148 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/lib/classes/' to classloader
   [junit4]   2> 236835 T2148 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10
   [junit4]   2> 236898 T2148 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 236899 T2148 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 236915 T2148 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 237371 T2148 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 237372 T2148 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 237372 T2148 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 237387 T2148 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 237390 T2148 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 237410 T2148 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 237415 T2148 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 237420 T2148 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 237421 T2148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 237421 T2148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 237421 T2148 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 237422 T2148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 237422 T2148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 237422 T2148 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1
   [junit4]   2> 237423 T2148 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 237423 T2148 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/, dataDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/data/
   [junit4]   2> 237423 T2148 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3f8c26ff
   [junit4]   2> 237425 T2148 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/data
   [junit4]   2> 237426 T2148 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/data/index/
   [junit4]   2> 237427 T2148 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/data/index' doesn't exist. Creating new index...
   [junit4]   2> 237427 T2148 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-003/collection1/data/index
   [junit4]   2> 237427 T2148 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=9, maxMergeAtOnceExplicit=5, maxMergedSegmentMB=1.2470703125, floorSegmentMB=2.1884765625, forceMergeDeletesPctAllowed=23.277766949976346, segmentsPerTier=21.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 237428 T2148 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RAMDirectory@659d4591 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@347c2827),segFN=segments_1,generation=1}
   [junit4]   2> 237428 T2148 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 237436 T2148 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 237436 T2148 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 237437 T2148 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 237437 T2148 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 237437 T2148 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 237437 T2148 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 237438 T2148 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 237438 T2148 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 237438 T2148 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 237439 T2148 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 237440 T2148 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 237440 T2148 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 237441 T2148 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 237442 T2148 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 237442 T2148 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 237443 T2148 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 237443 T2148 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 237444 T2148 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 237444 T2148 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 237444 T2148 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 237445 T2148 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 237464 T2148 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 237465 T2148 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 237467 T2148 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 237469 T2148 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 237471 T2148 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 237477 T2148 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 237477 T2148 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 237478 T2148 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=8, maxMergeAtOnceExplicit=6, maxMergedSegmentMB=90.3037109375, floorSegmentMB=0.8642578125, forceMergeDeletesPctAllowed=12.1405079704558, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 237478 T2148 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RAMDirectory@659d4591 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@347c2827),segFN=segments_1,generation=1}
   [junit4]   2> 237479 T2148 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 237480 T2148 oass.SolrIndexSearcher.<init> Opening Searcher@15ed71f4[collection1] main
   [junit4]   2> 237481 T2148 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 237482 T2148 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 237482 T2148 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
   [junit4]   2> 237482 T2148 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
   [junit4]   2> 237482 T2148 oasr.RestManager.init Initializing RestManager with initArgs: {}
   [junit4]   2> 237483 T2148 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 237483 T2148 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json
   [junit4]   2> 237484 T2148 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 237484 T2148 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
   [junit4]   2> 237484 T2148 oasr.RestManager.init Initializing 0 registered ManagedResources
   [junit4]   2> 237489 T2149 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15ed71f4[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 237494 T2148 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 237495 T2152 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33669/a/xe collection:collection1 shard:shard1
   [junit4]   2> 237495 T2098 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
   [junit4]   2> 237496 T2098 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 237496 T2152 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 237500 T2152 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 237501 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237502 T2152 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 237502 T2152 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C39 name=collection1 org.apache.solr.core.SolrCore@17535669 url=http://127.0.0.1:33669/a/xe/collection1 node=127.0.0.1:33669_a%2Fxe C39_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:33669/a/xe, core=collection1, node_name=127.0.0.1:33669_a%2Fxe}
   [junit4]   2> 237502 T2152 C39 P33669 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33669/a/xe/collection1/
   [junit4]   2> 237502 T2152 C39 P33669 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 237502 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 237503 T2152 C39 P33669 oasc.SyncStrategy.syncToMe http://127.0.0.1:33669/a/xe/collection1/ has no replicas
   [junit4]   2> 237503 T2152 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:33669/a/xe/collection1/ shard1
   [junit4]   2> 237503 T2152 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 237504 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237505 T2147 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> 237505 T2131 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> 237505 T2132 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> 237507 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237508 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 237510 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237611 T2131 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> 237611 T2147 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> 237611 T2132 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> 237660 T2152 oasc.ZkController.register We are http://127.0.0.1:33669/a/xe/collection1/ and leader is http://127.0.0.1:33669/a/xe/collection1/
   [junit4]   2> 237661 T2152 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33669/a/xe
   [junit4]   2> 237661 T2152 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 237661 T2152 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
   [junit4]   2> 237661 T2152 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 237663 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237663 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237663 T2152 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 237663 T2133 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237664 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 237664 T2121 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:33669/a/xe",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:33669_a%2Fxe",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":"core_node1"}
   [junit4]   2> 237666 T2133 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 237767 T2147 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> 237767 T2131 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> 237767 T2133 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> 238589 T2098 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 2
   [junit4]   2> 238590 T2098 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 238592 T2098 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:25102
   [junit4]   2> 238592 T2098 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 238593 T2098 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 238593 T2098 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004
   [junit4]   2> 238593 T2098 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/'
   [junit4]   2> 238623 T2098 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/solr.xml
   [junit4]   2> 238677 T2098 oasc.CoreContainer.<init> New CoreContainer 340173289
   [junit4]   2> 238677 T2098 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/]
   [junit4]   2> 238679 T2098 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 238679 T2098 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: 
   [junit4]   2> 238679 T2098 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 238679 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 238679 T2098 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 238680 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 238680 T2098 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 238680 T2098 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 238680 T2098 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 238681 T2098 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
   [junit4]   2> 238681 T2098 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 238681 T2098 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 238682 T2098 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 238682 T2098 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:37975/solr
   [junit4]   2> 238682 T2098 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 238683 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 238684 T2163 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5188dc4c name:ZooKeeperConnection Watcher:127.0.0.1:37975 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 238685 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 238687 T2098 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 238688 T2165 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52ca77d4 name:ZooKeeperConnection Watcher:127.0.0.1:37975/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 238688 T2098 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 238692 T2098 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 239695 T2098 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:25102_a%2Fxe
   [junit4]   2> 239696 T2098 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:25102_a%2Fxe
   [junit4]   2> 239698 T2133 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 239698 T2147 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 239698 T2166 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 239698 T2131 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 239718 T2167 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
   [junit4]   2> 239719 T2167 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 239720 T2167 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 239720 T2133 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 239720 T2124 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 239720 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 239721 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 239722 T2121 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:25102/a/xe",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:25102_a%2Fxe",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 239722 T2121 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
   [junit4]   2> 239722 T2121 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 239724 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 239724 T2166 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> 239724 T2131 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> 239724 T2147 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> 239724 T2132 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> 240720 T2167 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 240721 T2167 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 240721 T2167 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 240721 T2167 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 240722 T2167 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 240722 T2167 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/'
   [junit4]   2> 240725 T2167 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/lib/.svn/' to classloader
   [junit4]   2> 240725 T2167 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/lib/classes/' to classloader
   [junit4]   2> 240726 T2167 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/lib/README' to classloader
   [junit4]   2> 240792 T2167 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10
   [junit4]   2> 240842 T2167 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 240843 T2167 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 240858 T2167 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 241298 T2167 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 241299 T2167 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 241300 T2167 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 241309 T2167 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 241311 T2167 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 241326 T2167 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 241330 T2167 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 241332 T2167 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 241333 T2167 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 241333 T2167 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 241333 T2167 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 241334 T2167 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 241334 T2167 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 241334 T2167 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1
   [junit4]   2> 241334 T2167 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 241334 T2167 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/, dataDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/data/
   [junit4]   2> 241335 T2167 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3f8c26ff
   [junit4]   2> 241336 T2167 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/data
   [junit4]   2> 241337 T2167 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/data/index/
   [junit4]   2> 241337 T2167 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/data/index' doesn't exist. Creating new index...
   [junit4]   2> 241338 T2167 oasc.CachingDirectoryFactory.get return new directory for ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solr.cloud.MultiThreadedOCPTest-AB9A8892F2A68BB5-001/tempDir-004/collection1/data/index
   [junit4]   2> 241338 T2167 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=9, maxMergeAtOnceExplicit=5, maxMergedSegmentMB=1.2470703125, floorSegmentMB=2.1884765625, forceMergeDeletesPctAllowed=23.277766949976346, segmentsPerTier=21.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
   [junit4]   2> 241338 T2167 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RAMDirectory@65719564 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@64c9932f),segFN=segments_1,generation=1}
   [junit4]   2> 241339 T2167 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 241343 T2167 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 241344 T2167 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 241344 T2167 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 241344 T2167 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 241344 T2167 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 241344 T2167 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 241345 T2167 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 241345 T2167 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 241345 T2167 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 241346 T2167 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 241346 T2167 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 241347 T2167 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 241347 T2167 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 241347 T2167 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 241348 T2167 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 241348 T2167 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 241348 T2167 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 241349 T2167 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 241349 T2167 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 241349 T2167 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 241350 T2167 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 241362 T2167 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 241363 T2167 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 241365 T2167 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 241366 T2167 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 241367 T2167 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 241371 T2167 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 241371 T2167 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 241372 T2167 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=8, maxMergeAtOnceExplicit=6, maxMergedSegmentMB=90.3037109375, floorSegmentMB=0.8642578125, forceMergeDeletesPctAllowed=12.1405079704558, segmentsPerTier=20.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
   [junit4]   2> 241373 T2167 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=BaseDirectoryWrapper(RAMDirectory@65719564 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@64c9932f),segFN=segments_1,generation=1}
   [junit4]   2> 241373 T2167 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 241373 T2167 oass.SolrIndexSearcher.<init> Opening Searcher@19220923[collection1] main
   [junit4]   2> 241374 T2167 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 241374 T2167 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 241374 T2167 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
   [junit4]   2> 241375 T2167 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
   [junit4]   2> 241375 T2167 oasr.RestManager.init Initializing RestManager with initArgs: {}
   [junit4]   2> 241375 T2167 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 241375 T2167 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json
   [junit4]   2> 241376 T2167 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 241376 T2167 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
   [junit4]   2> 241376 T2167 oasr.RestManager.init Initializing 0 registered ManagedResources
   [junit4]   2> 241379 T2168 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19220923[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 241382 T2167 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 241383 T2171 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:25102/a/xe collection:collection1 shard:shard2
   [junit4]   2> 241383 T2098 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
   [junit4]   2> 241384 T2098 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 241384 T2171 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 241387 T2171 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
   [junit4]   2> 241388 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 241388 T2171 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 241389 T2171 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C40 name=collection1 org.apache.solr.core.SolrCore@189faa75 url=http://127.0.0.1:25102/a/xe/collection1 node=127.0.0.1:25102_a%2Fxe C40_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:25102/a/xe, core=collection1, node_name=127.0.0.1:25102_a%2Fxe}
   [junit4]   2> 241389 T2171 C40 P25102 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:25102/a/xe/collection1/
   [junit4]   2> 241389 T2171 C40 P25102 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 241389 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 241389 T2171 C40 P25102 oasc.SyncStrategy.syncToMe http://127.0.0.1:25102/a/xe/collection1/ has no replicas
   [junit4]   2> 241389 T2171 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:25102/a/xe/collection1/ shard2
   [junit4]   2> 241389 T2171 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 241391 T2132 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 241391 T2166 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> 241391 T2147 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> 241391 T2132 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> 241391 T2131 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged pa

[...truncated too long message...]

.java:608)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)Throwable #9: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=780101, name=qtp66094268-780101, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
   [junit4]    > Caused by: java.lang.OutOfMemoryError: unable to create new native thread
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([AB9A8892F2A68BB5]:0)
   [junit4]    > 	at java.lang.Thread.start0(Native Method)
   [junit4]    > 	at java.lang.Thread.start(Thread.java:714)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1047)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1312)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1339)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1323)
   [junit4]    > 	at org.eclipse.jetty.server.ssl.SslSocketConnector$SslConnectorEndPoint.run(SslSocketConnector.java:665)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)Throwable #10: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=780096, name=qtp860896798-780096, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
   [junit4]    > Caused by: java.lang.OutOfMemoryError: unable to create new native thread
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([AB9A8892F2A68BB5]:0)
   [junit4]    > 	at java.lang.Thread.start0(Native Method)
   [junit4]    > 	at java.lang.Thread.start(Thread.java:714)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1047)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1312)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1339)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1323)
   [junit4]    > 	at org.eclipse.jetty.server.ssl.SslSocketConnector$SslConnectorEndPoint.run(SslSocketConnector.java:665)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)Throwable #11: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=780155, name=RecoveryThread, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
   [junit4]    > Caused by: java.lang.OutOfMemoryError: unable to create new native thread
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([AB9A8892F2A68BB5]:0)
   [junit4]    > 	at java.lang.Thread.start0(Native Method)
   [junit4]    > 	at java.lang.Thread.start(Thread.java:714)
   [junit4]    > 	at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:949)
   [junit4]    > 	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1360)
   [junit4]    > 	at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:132)
   [junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.httpUriRequest(HttpSolrServer.java:241)
   [junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.httpUriRequest(HttpSolrServer.java:230)
   [junit4]    > 	at org.apache.solr.cloud.RecoveryStrategy.sendPrepRecoveryCmd(RecoveryStrategy.java:610)
   [junit4]    > 	at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:371)
   [junit4]    > 	at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:235)Throwable #12: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=779767, name=qtp66094268-779767, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
   [junit4]    > Caused by: java.lang.OutOfMemoryError: unable to create new native thread
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([AB9A8892F2A68BB5]:0)
   [junit4]    > 	at java.lang.Thread.start0(Native Method)
   [junit4]    > 	at java.lang.Thread.start(Thread.java:714)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1047)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1312)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1339)
   [junit4]    > 	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1323)
   [junit4]    > 	at org.eclipse.jetty.server.ssl.SslSocketConnector$SslConnectorEndPoint.run(SslSocketConnector.java:665)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
   [junit4]    > 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)
   [junit4]   2> 3570756 T771884 oas.SolrTestCaseJ4.deleteCore ###deleteCore
   [junit4]   2> NOTE: test params are: codec=HighCompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=494), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=494)), sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=zh_SG, timezone=Africa/Harare
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=193193280,total=512229376
   [junit4]   2> NOTE: All tests run in this JVM: [ChaosMonkeySafeLeaderTest, TestLazyCores, TestCollectionAPI, SampleTest, TimeZoneUtilsTest, DistributedQueryElevationComponentTest, DistribCursorPagingTest, TestGroupingSearch, ShardSplitTest, DocValuesMissingTest, DOMUtilTest, TestNoOpRegenerator, TestPseudoReturnFields, TestMissingGroups, DeleteInactiveReplicaTest, TestLeaderElectionZkExpiry, ScriptEngineTest, CopyFieldTest, SpellingQueryConverterTest, SolrRequestParserTest, DistributedQueryComponentCustomSortTest, LukeRequestHandlerTest, TestSolrQueryParserDefaultOperatorResource, TestElisionMultitermQuery, TestQuerySenderNoQuery, TestQueryUtils, TestIndexingPerformance, QueryElevationComponentTest, CoreAdminRequestStatusTest, TestCSVResponseWriter, TestAddFieldRealTimeGet, TestPHPSerializedResponseWriter, FileUtilsTest, SpatialFilterTest, TestCoreContainer, TestBadConfig, AlternateDirectoryTest, TestImplicitCoreProperties, TestDocumentBuilder, SearchHandlerTest, TestOverriddenPrefixQueryForCustomFieldType, DeleteReplicaTest, CurrencyFieldXmlFileTest, AddBlockUpdateTest, SolrCoreTest, DistributedSuggestComponentTest, AutoCommitTest, OpenCloseCoreStressTest, TestPhraseSuggestions, TestMultiCoreConfBootstrap, TestCharFilters, TestSerializedLuceneMatchVersion, TestBinaryField, TestRTGBase, TestFiltering, TestSuggestSpellingConverter, BasicZkTest, TestIndexSearcher, SystemInfoHandlerTest, FileBasedSpellCheckerTest, TestUniqueKeyFieldResource, TestLMDirichletSimilarityFactory, TestDocBasedVersionConstraints, SimplePostToolTest, TestOmitPositions, CoreMergeIndexesAdminHandlerTest, TestRandomFaceting, HighlighterMaxOffsetTest, TestRecovery, SortByFunctionTest, AddSchemaFieldsUpdateProcessorFactoryTest, SolrInfoMBeanTest, TestManagedSchemaFieldResource, TestIBSimilarityFactory, HdfsLockFactoryTest, TestSolrQueryParser, FullSolrCloudDistribCmdsTest, DistributedQueryComponentOptimizationTest, TestCursorMarkWithoutUniqueKey, ConnectionManagerTest, ResponseHeaderTest, TestSchemaNameResource, NumericFieldsTest, TestInfoStreamLogging, SOLR749Test, LoggingHandlerTest, CSVRequestHandlerTest, BasicDistributedZk2Test, TestExtendedDismaxParser, TestManagedStopFilterFactory, DistanceFunctionTest, TestSchemaSimilarityResource, TestJoin, CacheHeaderTest, TestShardHandlerFactory, TestMergePolicyConfig, RequestHandlersTest, BasicDistributedZkTest, CollectionsAPIDistributedZkTest]
   [junit4] Completed on J1 in 378.59s, 1 test, 1 error <<< FAILURES!

[...truncated 685 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:474: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:447: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:45: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/common-build.xml:496: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1299: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:923: There were test failures: 411 suites, 1707 tests, 1 error, 1 failure, 50 ignored (8 assumptions)

Total time: 261 minutes 1 second
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-NightlyTests-4.x #586
Archived 3 artifacts
Archive block size is 32768
Received 0 blocks and 460166856 bytes
Compression is 0.0%
Took 1 min 14 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Re: [JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 594 - Still Failing

Posted by Michael McCandless <lu...@mikemccandless.com>.
I committed a fix ...

Mike McCandless

http://blog.mikemccandless.com


On Sat, Aug 9, 2014 at 11:39 AM, Apache Jenkins Server
<je...@builds.apache.org> wrote:
> Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/594/
>
> 1 tests failed.
> REGRESSION:  org.apache.lucene.index.TestFlushByRamOrCountsPolicy.testFlushDocCount
>
> Error Message:
> Captured an uncaught exception in thread: Thread[id=3560, name=Thread-2881, state=RUNNABLE, group=TGRP-TestFlushByRamOrCountsPolicy]
>
> Stack Trace:
> com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3560, name=Thread-2881, state=RUNNABLE, group=TGRP-TestFlushByRamOrCountsPolicy]
> Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
>         at __randomizedtesting.SeedInfo.seed([A89700DEDEDF8395]:0)
>         at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:331)
> Caused by: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
>         at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:671)
>         at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:342)
>         at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
>         at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
>         at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
>         at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
>         at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1254)
>         at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235)
>         at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:316)
> Caused by: org.apache.lucene.util.BytesRefHash$MaxBytesLengthExceededException: bytes can be at most 32766 in length; got 94384
>         at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:284)
>         at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:151)
>         at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:645)
>         ... 8 more
>         Suppressed: java.lang.AssertionError: close() called in wrong state: INCREMENT
>                 at org.apache.lucene.analysis.MockTokenizer.close(MockTokenizer.java:262)
>                 at org.apache.lucene.analysis.TokenFilter.close(TokenFilter.java:58)
>                 at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:661)
>                 ... 8 more
>
>
>
>
> Build Log:
> [...truncated 1120 lines...]
>    [junit4] Suite: org.apache.lucene.index.TestFlushByRamOrCountsPolicy
>    [junit4]   1> FAILED exc:
>    [junit4]   1> java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
>    [junit4]   1>        at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:671)
>    [junit4]   1>        at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:342)
>    [junit4]   1>        at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
>    [junit4]   1>        at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
>    [junit4]   1>        at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
>    [junit4]   1>        at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
>    [junit4]   1>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1254)
>    [junit4]   1>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235)
>    [junit4]   1>        at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:316)
>    [junit4]   1> Caused by: org.apache.lucene.util.BytesRefHash$MaxBytesLengthExceededException: bytes can be at most 32766 in length; got 94384
>    [junit4]   1>        at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:284)
>    [junit4]   1>        at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:151)
>    [junit4]   1>        at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:645)
>    [junit4]   1>        ... 8 more
>    [junit4]   1>        Suppressed: java.lang.AssertionError: close() called in wrong state: INCREMENT
>    [junit4]   1>                at org.apache.lucene.analysis.MockTokenizer.close(MockTokenizer.java:262)
>    [junit4]   1>                at org.apache.lucene.analysis.TokenFilter.close(TokenFilter.java:58)
>    [junit4]   1>                at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:661)
>    [junit4]   1>                ... 8 more
>    [junit4]   2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
>    [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestFlushByRamOrCountsPolicy -Dtests.method=testFlushDocCount -Dtests.seed=A89700DEDEDF8395 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=es_EC -Dtests.timezone=US/Michigan -Dtests.file.encoding=US-ASCII
>    [junit4] ERROR   0.54s J0 | TestFlushByRamOrCountsPolicy.testFlushDocCount <<<
>    [junit4]    > Throwable #1: java.lang.AssertionError: expected:<170> but was:<101>
>    [junit4]    >        at org.apache.lucene.index.TestFlushByRamOrCountsPolicy.testFlushDocCount(TestFlushByRamOrCountsPolicy.java:160)
>    [junit4]    >        at java.lang.Thread.run(Thread.java:745)Throwable #2: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3560, name=Thread-2881, state=RUNNABLE, group=TGRP-TestFlushByRamOrCountsPolicy]
>    [junit4]    > Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
>    [junit4]    >        at __randomizedtesting.SeedInfo.seed([A89700DEDEDF8395]:0)
>    [junit4]    >        at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:331)
>    [junit4]    > Caused by: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
>    [junit4]    >        at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:671)
>    [junit4]    >        at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:342)
>    [junit4]    >        at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
>    [junit4]    >        at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
>    [junit4]    >        at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
>    [junit4]    >        at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
>    [junit4]    >        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1254)
>    [junit4]    >        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235)
>    [junit4]    >        at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:316)
>    [junit4]    > Caused by: org.apache.lucene.util.BytesRefHash$MaxBytesLengthExceededException: bytes can be at most 32766 in length; got 94384
>    [junit4]    >        at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:284)
>    [junit4]    >        at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:151)
>    [junit4]    >        at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:645)
>    [junit4]    >        ... 8 more
>    [junit4]    >        Suppressed: java.lang.AssertionError: close() called in wrong state: INCREMENT
>    [junit4]    >                at org.apache.lucene.analysis.MockTokenizer.close(MockTokenizer.java:262)
>    [junit4]    >                at org.apache.lucene.analysis.TokenFilter.close(TokenFilter.java:58)
>    [junit4]    >                at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:661)
>    [junit4]    >                ... 8 more
>    [junit4]   2> NOTE: leaving temporary files on disk at: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/build/core/test/J0/./lucene.index.TestFlushByRamOrCountsPolicy-A89700DEDEDF8395-001
>    [junit4]   2> NOTE: test params are: codec=Lucene49: {titleTokenized=PostingsFormat(name=Memory doPackFST= false), date=Pulsing41(freqCutoff=9 minBlockSize=35 maxBlockSize=138), body=Pulsing41(freqCutoff=9 minBlockSize=35 maxBlockSize=138), title=Pulsing41(freqCutoff=15 minBlockSize=35 maxBlockSize=138), docid=FSTOrd41}, docValues:{titleDV=DocValuesFormat(name=Memory)}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {titleTokenized=DFR G1, body=DFR I(n)L1}, locale=es_EC, timezone=US/Michigan
>    [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=213787512,total=457703424
>    [junit4]   2> NOTE: All tests run in this JVM: [TestSimilarityProvider, TestSearch, TestLockFactory, TestIndexWriterCommit, TestLazyProxSkipping, TestCompiledAutomaton, TestTermsEnum, ThrowInUncaught, TestFilteredSearch, TestSloppyPhraseQuery, TestScoreCachingWrappingScorer, TestNumericDocValuesUpdates, TestAllFilesHaveCodecHeader, TestDemo, TestNoDeletionPolicy, TestCharTermAttributeImpl, TestMultiValuedNumericRangeQuery, TestNearSpansOrdered, TestDeletionPolicy, TestBytesStore, TestScorerPerf, Nested, Nested, TestOmitPositions, TestDocTermOrdsRewriteMethod, TestFieldsReader, TestTwoPhaseCommitTool, TestSearcherManager, TestNoMergeScheduler, TestSortRescorer, TestDoc, TestQueryWrapperFilter, TestSearchAfter, TestSort, Test2BPostings, TestFieldCacheRewriteMethod, TestLock, TestSimpleAttributeImpl, TestVirtualMethod, TestBufferedChecksum, TestBytesRef, TestFieldReuse, TestPForDeltaDocIdSet, TestIndexableBinaryStringTools, TestIndexableField, TestEarlyTermination, TestPriorityQueue, TestIndexSearcher, TestPerSegmentDeletes, TestMultiPhraseQuery, TestIndexWriterReader, TestNumericRangeQuery32, TestLucene42DocValuesFormat, TestDocValuesWithThreads, TestLookaheadTokenFilter, TestForceMergeForever, TestIndexCommit, TestTermScorer, Test2BBinaryDocValues, TestIndexWriterConfig, TestIntroSorter, TestLiveFieldValues, TestPrefixRandom, TestMathUtil, TestMultiTermQueryRewrites, TestSpans, TestBagOfPostings, TestTermsEnum2, TestFastDecompressionMode, TestFilterIterator, TestIndexWriterExceptions2, TestStoredFieldsFormat, TestSentinelIntSet, TestTopScoreDocCollector, TestStressNRT, TestReuseDocsEnum, TestMergeSchedulerExternal, Test2BPostingsBytes, TestDocIdBitSet, TestIndexReaderClose, TestExceedMaxTermLength, TestTerms, TestPersistentSnapshotDeletionPolicy, TestPhraseQuery, TestUTF32ToUTF8, TestComplexExplanations, TestLucene45DocValuesFormat, TestSpanExplanations, TestQueryRescorer, TestTopDocsCollector, TestTopFieldCollector, TestReusableStringReader, TestSetOnce, Test2BPagedBytes, TestPostingsFormat, TestPhrasePrefixQuery, TestBinaryDocValuesUpdates, TestByteSlices, TestCrash, TestLongBitSet, TestTermVectors, TestCompoundFile, TestIndexWriterForceMerge, TestIndexWriterLockRelease, TestPayloadsOnVectors, TestRecyclingByteBlockAllocator, TestBlockPostingsFormat3, TestFlushByRamOrCountsPolicy]
>    [junit4] Completed on J0 in 10.63s, 5 tests, 1 error <<< FAILURES!
>
> [...truncated 719 lines...]
> BUILD FAILED
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:481: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:454: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:45: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/extra-targets.xml:37: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/build.xml:49: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1299: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:923: There were test failures: 417 suites, 3600 tests, 1 error, 129 ignored (118 assumptions)
>
> Total time: 88 minutes 55 seconds
> Build step 'Invoke Ant' marked build as failure
> Archiving artifacts
> Sending artifact delta relative to Lucene-Solr-NightlyTests-4.x #586
> Archived 3 artifacts
> Archive block size is 32768
> Received 0 blocks and 4826209 bytes
> Compression is 0.0%
> Took 3.1 sec
> Recording test results
> Email was triggered for: Failure
> Sending email for trigger: Failure
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org


[JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 594 - Still Failing

Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/594/

1 tests failed.
REGRESSION:  org.apache.lucene.index.TestFlushByRamOrCountsPolicy.testFlushDocCount

Error Message:
Captured an uncaught exception in thread: Thread[id=3560, name=Thread-2881, state=RUNNABLE, group=TGRP-TestFlushByRamOrCountsPolicy]

Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3560, name=Thread-2881, state=RUNNABLE, group=TGRP-TestFlushByRamOrCountsPolicy]
Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
	at __randomizedtesting.SeedInfo.seed([A89700DEDEDF8395]:0)
	at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:331)
Caused by: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:671)
	at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:342)
	at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
	at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
	at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1254)
	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235)
	at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:316)
Caused by: org.apache.lucene.util.BytesRefHash$MaxBytesLengthExceededException: bytes can be at most 32766 in length; got 94384
	at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:284)
	at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:151)
	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:645)
	... 8 more
	Suppressed: java.lang.AssertionError: close() called in wrong state: INCREMENT
		at org.apache.lucene.analysis.MockTokenizer.close(MockTokenizer.java:262)
		at org.apache.lucene.analysis.TokenFilter.close(TokenFilter.java:58)
		at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:661)
		... 8 more




Build Log:
[...truncated 1120 lines...]
   [junit4] Suite: org.apache.lucene.index.TestFlushByRamOrCountsPolicy
   [junit4]   1> FAILED exc:
   [junit4]   1> java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
   [junit4]   1> 	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:671)
   [junit4]   1> 	at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:342)
   [junit4]   1> 	at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
   [junit4]   1> 	at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
   [junit4]   1> 	at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
   [junit4]   1> 	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
   [junit4]   1> 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1254)
   [junit4]   1> 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235)
   [junit4]   1> 	at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:316)
   [junit4]   1> Caused by: org.apache.lucene.util.BytesRefHash$MaxBytesLengthExceededException: bytes can be at most 32766 in length; got 94384
   [junit4]   1> 	at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:284)
   [junit4]   1> 	at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:151)
   [junit4]   1> 	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:645)
   [junit4]   1> 	... 8 more
   [junit4]   1> 	Suppressed: java.lang.AssertionError: close() called in wrong state: INCREMENT
   [junit4]   1> 		at org.apache.lucene.analysis.MockTokenizer.close(MockTokenizer.java:262)
   [junit4]   1> 		at org.apache.lucene.analysis.TokenFilter.close(TokenFilter.java:58)
   [junit4]   1> 		at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:661)
   [junit4]   1> 		... 8 more
   [junit4]   2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
   [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=TestFlushByRamOrCountsPolicy -Dtests.method=testFlushDocCount -Dtests.seed=A89700DEDEDF8395 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=es_EC -Dtests.timezone=US/Michigan -Dtests.file.encoding=US-ASCII
   [junit4] ERROR   0.54s J0 | TestFlushByRamOrCountsPolicy.testFlushDocCount <<<
   [junit4]    > Throwable #1: java.lang.AssertionError: expected:<170> but was:<101>
   [junit4]    > 	at org.apache.lucene.index.TestFlushByRamOrCountsPolicy.testFlushDocCount(TestFlushByRamOrCountsPolicy.java:160)
   [junit4]    > 	at java.lang.Thread.run(Thread.java:745)Throwable #2: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3560, name=Thread-2881, state=RUNNABLE, group=TGRP-TestFlushByRamOrCountsPolicy]
   [junit4]    > Caused by: java.lang.RuntimeException: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
   [junit4]    > 	at __randomizedtesting.SeedInfo.seed([A89700DEDEDF8395]:0)
   [junit4]    > 	at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:331)
   [junit4]    > Caused by: java.lang.IllegalArgumentException: Document contains at least one immense term in field="body" (whose UTF8 encoding is longer than the max length 32766), all of which were skipped.  Please correct the analyzer to not produce such terms.  The prefix of the first immense term is: '[125, 125, 123, 123, 123, 123, 123, 115, 117, 98, 115, 116, 99, 124, 125, 125, 125, 123, 123, 123, 49, 125, 125, 125, 124, 123, 123, 123, 112, 49]...', original message: bytes can be at most 32766 in length; got 94384
   [junit4]    > 	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:671)
   [junit4]    > 	at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:342)
   [junit4]    > 	at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
   [junit4]    > 	at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
   [junit4]    > 	at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1254)
   [junit4]    > 	at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235)
   [junit4]    > 	at org.apache.lucene.index.TestFlushByRamOrCountsPolicy$IndexThread.run(TestFlushByRamOrCountsPolicy.java:316)
   [junit4]    > Caused by: org.apache.lucene.util.BytesRefHash$MaxBytesLengthExceededException: bytes can be at most 32766 in length; got 94384
   [junit4]    > 	at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:284)
   [junit4]    > 	at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:151)
   [junit4]    > 	at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:645)
   [junit4]    > 	... 8 more
   [junit4]    > 	Suppressed: java.lang.AssertionError: close() called in wrong state: INCREMENT
   [junit4]    > 		at org.apache.lucene.analysis.MockTokenizer.close(MockTokenizer.java:262)
   [junit4]    > 		at org.apache.lucene.analysis.TokenFilter.close(TokenFilter.java:58)
   [junit4]    > 		at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:661)
   [junit4]    > 		... 8 more
   [junit4]   2> NOTE: leaving temporary files on disk at: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/build/core/test/J0/./lucene.index.TestFlushByRamOrCountsPolicy-A89700DEDEDF8395-001
   [junit4]   2> NOTE: test params are: codec=Lucene49: {titleTokenized=PostingsFormat(name=Memory doPackFST= false), date=Pulsing41(freqCutoff=9 minBlockSize=35 maxBlockSize=138), body=Pulsing41(freqCutoff=9 minBlockSize=35 maxBlockSize=138), title=Pulsing41(freqCutoff=15 minBlockSize=35 maxBlockSize=138), docid=FSTOrd41}, docValues:{titleDV=DocValuesFormat(name=Memory)}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {titleTokenized=DFR G1, body=DFR I(n)L1}, locale=es_EC, timezone=US/Michigan
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=213787512,total=457703424
   [junit4]   2> NOTE: All tests run in this JVM: [TestSimilarityProvider, TestSearch, TestLockFactory, TestIndexWriterCommit, TestLazyProxSkipping, TestCompiledAutomaton, TestTermsEnum, ThrowInUncaught, TestFilteredSearch, TestSloppyPhraseQuery, TestScoreCachingWrappingScorer, TestNumericDocValuesUpdates, TestAllFilesHaveCodecHeader, TestDemo, TestNoDeletionPolicy, TestCharTermAttributeImpl, TestMultiValuedNumericRangeQuery, TestNearSpansOrdered, TestDeletionPolicy, TestBytesStore, TestScorerPerf, Nested, Nested, TestOmitPositions, TestDocTermOrdsRewriteMethod, TestFieldsReader, TestTwoPhaseCommitTool, TestSearcherManager, TestNoMergeScheduler, TestSortRescorer, TestDoc, TestQueryWrapperFilter, TestSearchAfter, TestSort, Test2BPostings, TestFieldCacheRewriteMethod, TestLock, TestSimpleAttributeImpl, TestVirtualMethod, TestBufferedChecksum, TestBytesRef, TestFieldReuse, TestPForDeltaDocIdSet, TestIndexableBinaryStringTools, TestIndexableField, TestEarlyTermination, TestPriorityQueue, TestIndexSearcher, TestPerSegmentDeletes, TestMultiPhraseQuery, TestIndexWriterReader, TestNumericRangeQuery32, TestLucene42DocValuesFormat, TestDocValuesWithThreads, TestLookaheadTokenFilter, TestForceMergeForever, TestIndexCommit, TestTermScorer, Test2BBinaryDocValues, TestIndexWriterConfig, TestIntroSorter, TestLiveFieldValues, TestPrefixRandom, TestMathUtil, TestMultiTermQueryRewrites, TestSpans, TestBagOfPostings, TestTermsEnum2, TestFastDecompressionMode, TestFilterIterator, TestIndexWriterExceptions2, TestStoredFieldsFormat, TestSentinelIntSet, TestTopScoreDocCollector, TestStressNRT, TestReuseDocsEnum, TestMergeSchedulerExternal, Test2BPostingsBytes, TestDocIdBitSet, TestIndexReaderClose, TestExceedMaxTermLength, TestTerms, TestPersistentSnapshotDeletionPolicy, TestPhraseQuery, TestUTF32ToUTF8, TestComplexExplanations, TestLucene45DocValuesFormat, TestSpanExplanations, TestQueryRescorer, TestTopDocsCollector, TestTopFieldCollector, TestReusableStringReader, TestSetOnce, Test2BPagedBytes, TestPostingsFormat, TestPhrasePrefixQuery, TestBinaryDocValuesUpdates, TestByteSlices, TestCrash, TestLongBitSet, TestTermVectors, TestCompoundFile, TestIndexWriterForceMerge, TestIndexWriterLockRelease, TestPayloadsOnVectors, TestRecyclingByteBlockAllocator, TestBlockPostingsFormat3, TestFlushByRamOrCountsPolicy]
   [junit4] Completed on J0 in 10.63s, 5 tests, 1 error <<< FAILURES!

[...truncated 719 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:481: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:454: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:45: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/build.xml:49: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1299: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:923: There were test failures: 417 suites, 3600 tests, 1 error, 129 ignored (118 assumptions)

Total time: 88 minutes 55 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-NightlyTests-4.x #586
Archived 3 artifacts
Archive block size is 32768
Received 0 blocks and 4826209 bytes
Compression is 0.0%
Took 3.1 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



[JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 593 - Still Failing

Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/593/

1 tests failed.
REGRESSION:  org.apache.solr.cloud.FullSolrCloudDistribCmdsTest.testDistribSearch

Error Message:
IOException occured when talking to server at: http://127.0.0.1:30047/_sd/ya/collection1

Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:30047/_sd/ya/collection1
	at __randomizedtesting.SeedInfo.seed([2F90961CE3B07E66:AE76180494EF1E5A]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.executeMethod(HttpSolrServer.java:563)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:210)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:206)
	at org.apache.solr.client.solrj.request.QueryRequest.process(QueryRequest.java:91)
	at org.apache.solr.client.solrj.SolrServer.query(SolrServer.java:301)
	at org.apache.solr.cloud.CloudInspectUtil.compareResults(CloudInspectUtil.java:223)
	at org.apache.solr.cloud.CloudInspectUtil.compareResults(CloudInspectUtil.java:165)
	at org.apache.solr.cloud.FullSolrCloudDistribCmdsTest.testIndexingBatchPerRequestWithHttpSolrServer(FullSolrCloudDistribCmdsTest.java:414)
	at org.apache.solr.cloud.FullSolrCloudDistribCmdsTest.doTest(FullSolrCloudDistribCmdsTest.java:144)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:867)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.SocketException: Broken pipe
	at java.net.SocketOutputStream.socketWrite0(Native Method)
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
	at org.apache.http.impl.io.AbstractSessionOutputBuffer.flushBuffer(AbstractSessionOutputBuffer.java:159)
	at org.apache.http.impl.io.AbstractSessionOutputBuffer.writeLine(AbstractSessionOutputBuffer.java:258)
	at org.apache.http.impl.io.HttpRequestWriter.writeHeadLine(HttpRequestWriter.java:59)
	at org.apache.http.impl.io.HttpRequestWriter.writeHeadLine(HttpRequestWriter.java:46)
	at org.apache.http.impl.io.AbstractMessageWriter.write(AbstractMessageWriter.java:109)
	at org.apache.http.impl.AbstractHttpClientConnection.sendRequestHeader(AbstractHttpClientConnection.java:254)
	at org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader(DefaultClientConnection.java:270)
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.sendRequestHeader(ManagedClientConnectionImpl.java:209)
	at org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:203)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:682)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:486)
	at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.executeMethod(HttpSolrServer.java:449)
	... 50 more




Build Log:
[...truncated 14190 lines...]
   [junit4] Suite: org.apache.solr.cloud.FullSolrCloudDistribCmdsTest
   [junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/init-core-data-001
   [junit4]   2> 3858921 T11953 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_sd/ya
   [junit4]   2> 3858924 T11953 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
   [junit4]   2> 3858925 T11953 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   1> client port:0.0.0.0/0.0.0.0:0
   [junit4]   2> 3858926 T11954 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 3859026 T11953 oasc.ZkTestServer.run start zk server on port:53895
   [junit4]   2> 3859027 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3859031 T11960 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11afc564 name:ZooKeeperConnection Watcher:127.0.0.1:53895 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3859031 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3859031 T11953 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 3859035 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3859036 T11962 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6bdf7d45 name:ZooKeeperConnection Watcher:127.0.0.1:53895/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3859036 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3859036 T11953 oascc.SolrZkClient.makePath makePath: /collections/collection1
   [junit4]   2> 3859038 T11953 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
   [junit4]   2> 3859039 T11953 oascc.SolrZkClient.makePath makePath: /collections/control_collection
   [junit4]   2> 3859040 T11953 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
   [junit4]   2> 3859042 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
   [junit4]   2> 3859042 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
   [junit4]   2> 3859044 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
   [junit4]   2> 3859045 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
   [junit4]   2> 3859147 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 3859148 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 3859150 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
   [junit4]   2> 3859150 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
   [junit4]   2> 3859152 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
   [junit4]   2> 3859153 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
   [junit4]   2> 3859154 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
   [junit4]   2> 3859155 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
   [junit4]   2> 3859157 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
   [junit4]   2> 3859157 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml
   [junit4]   2> 3859159 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
   [junit4]   2> 3859160 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
   [junit4]   2> 3859162 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 3859162 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 3859164 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
   [junit4]   2> 3859165 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
   [junit4]   2> 3859166 T11953 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
   [junit4]   2> 3859167 T11953 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
   [junit4]   2> 3860300 T11953 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 3860305 T11953 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:30047
   [junit4]   2> 3860305 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 3860306 T11953 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 3860306 T11953 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002
   [junit4]   2> 3860306 T11953 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/'
   [junit4]   2> 3860336 T11953 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/solr.xml
   [junit4]   2> 3860387 T11953 oasc.CoreContainer.<init> New CoreContainer 990570062
   [junit4]   2> 3860387 T11953 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/]
   [junit4]   2> 3860388 T11953 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 3860388 T11953 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: 
   [junit4]   2> 3860388 T11953 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 3860389 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 3860389 T11953 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 3860389 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 3860389 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 3860390 T11953 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 3860390 T11953 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 3860390 T11953 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
   [junit4]   2> 3860391 T11953 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 3860391 T11953 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 3860391 T11953 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 3860391 T11953 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53895/solr
   [junit4]   2> 3860392 T11953 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 3860392 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3860394 T11973 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4896292a name:ZooKeeperConnection Watcher:127.0.0.1:53895 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3860394 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3860397 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3860398 T11975 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f926a08 name:ZooKeeperConnection Watcher:127.0.0.1:53895/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3860398 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3860400 T11953 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 3860402 T11953 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 3860403 T11953 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
   [junit4]   2> 3860405 T11953 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
   [junit4]   2> 3860407 T11953 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
   [junit4]   2> 3860409 T11953 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 3860410 T11953 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:30047__sd%2Fya
   [junit4]   2> 3860411 T11953 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:30047__sd%2Fya
   [junit4]   2> 3860412 T11953 oascc.SolrZkClient.makePath makePath: /overseer_elect
   [junit4]   2> 3860414 T11953 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 3860416 T11953 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:30047__sd%2Fya
   [junit4]   2> 3860416 T11953 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 3860417 T11953 oasc.Overseer.start Overseer (id=92242611182895107-127.0.0.1:30047__sd%2Fya-n_0000000000) starting
   [junit4]   2> 3860419 T11953 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 3860424 T11977 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 3860424 T11953 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 3860426 T11953 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 3860427 T11953 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 3860429 T11976 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 3860434 T11978 oasc.ZkController.publish publishing core=collection1 state=down collection=control_collection
   [junit4]   2> 3860434 T11978 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 3860435 T11978 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 3860435 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3860436 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3860436 T11976 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:30047/_sd/ya",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:30047__sd%2Fya",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 3860437 T11976 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
   [junit4]   2> 3860437 T11976 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 3860439 T11979 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> 3861435 T11978 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 3861436 T11978 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
   [junit4]   2> 3861436 T11978 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 3861437 T11978 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
   [junit4]   2> 3861437 T11978 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 3861438 T11978 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/collection1/'
   [junit4]   2> 3861440 T11978 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/collection1/lib/classes/' to classloader
   [junit4]   2> 3861440 T11978 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/collection1/lib/README' to classloader
   [junit4]   2> 3861441 T11978 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/collection1/lib/.svn/' to classloader
   [junit4]   2> 3861503 T11978 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10
   [junit4]   2> 3861546 T11978 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 3861647 T11978 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 3861656 T11978 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 3862023 T11978 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 3862026 T11978 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 3862028 T11978 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3862032 T11978 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3862048 T11978 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection control_collection
   [junit4]   2> 3862048 T11978 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 3862049 T11978 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-002/collection1/, dataDir=./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/control/data/
   [junit4]   2> 3862049 T11978 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@290f6b0c
   [junit4]   2> 3862051 T11978 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/control/data
   [junit4]   2> 3862051 T11978 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/control/data/index/
   [junit4]   2> 3862052 T11978 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/control/data/index' doesn't exist. Creating new index...
   [junit4]   2> 3862053 T11978 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/control/data/index
   [junit4]   2> 3862053 T11978 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=6, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
   [junit4]   2> 3862056 T11978 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirectoryWrapper(SimpleFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/index-SimpleFSDirectory-001 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@fb9c1a),segFN=segments_1,generation=1}
   [junit4]   2> 3862056 T11978 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3862059 T11978 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 3862059 T11978 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 3862060 T11978 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 3862060 T11978 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 3862060 T11978 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 3862060 T11978 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 3862061 T11978 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 3862061 T11978 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 3862061 T11978 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 3862062 T11978 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3862062 T11978 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3862063 T11978 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3862063 T11978 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3862064 T11978 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 3862064 T11978 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 3862064 T11978 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 3862064 T11978 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 3862065 T11978 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3862065 T11978 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 3862065 T11978 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 3862066 T11978 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 3862085 T11978 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3862087 T11978 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3862088 T11978 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3862090 T11978 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3862092 T11978 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3862098 T11978 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 3862098 T11978 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 3862099 T11978 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1470702014, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
   [junit4]   2> 3862101 T11978 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirectoryWrapper(SimpleFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/index-SimpleFSDirectory-001 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@fb9c1a),segFN=segments_1,generation=1}
   [junit4]   2> 3862101 T11978 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3862101 T11978 oass.SolrIndexSearcher.<init> Opening Searcher@7e4478[collection1] main
   [junit4]   2> 3862102 T11978 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
   [junit4]   2> 3862102 T11978 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 3862103 T11978 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
   [junit4]   2> 3862103 T11978 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
   [junit4]   2> 3862103 T11978 oasr.RestManager.init Initializing RestManager with initArgs: {}
   [junit4]   2> 3862104 T11978 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3862104 T11978 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream No data found for znode /configs/conf1/_rest_managed.json
   [junit4]   2> 3862104 T11978 oasr.ManagedResourceStorage.load Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3862105 T11978 oascc.SolrZkClient.makePath makePath: /configs/conf1/_rest_managed.json
   [junit4]   2> 3862106 T11978 oasr.ManagedResourceStorage$ZooKeeperStorageIO$1.close Wrote 38 bytes to new znode /configs/conf1/_rest_managed.json
   [junit4]   2> 3862107 T11978 oasr.ManagedResourceStorage$JsonStorage.store Saved JSON object to path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3862107 T11978 oasr.RestManager.init Initializing 0 registered ManagedResources
   [junit4]   2> 3862109 T11980 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e4478[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 3862111 T11978 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 3862111 T11983 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:30047/_sd/ya collection:control_collection shard:shard1
   [junit4]   2> 3862112 T11953 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1
   [junit4]   2> 3862112 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 3862112 T11983 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
   [junit4]   2> 3862113 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3862115 T11985 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c5a71b3 name:ZooKeeperConnection Watcher:127.0.0.1:53895/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3862115 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3862118 T11953 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 3862119 T11983 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 3862119 T11953 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false
   [junit4]   2> 3862120 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3862120 T11983 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 3862121 T11983 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C11446 name=collection1 org.apache.solr.core.SolrCore@648819c8 url=http://127.0.0.1:30047/_sd/ya/collection1 node=127.0.0.1:30047__sd%2Fya C11446_STATE=coll:control_collection core:collection1 props:{state=down, base_url=http://127.0.0.1:30047/_sd/ya, core=collection1, node_name=127.0.0.1:30047__sd%2Fya}
   [junit4]   2> 3862121 T11983 C11446 P30047 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:30047/_sd/ya/collection1/
   [junit4]   2> 3862121 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3862121 T11983 C11446 P30047 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 3862122 T11983 C11446 P30047 oasc.SyncStrategy.syncToMe http://127.0.0.1:30047/_sd/ya/collection1/ has no replicas
   [junit4]   2> 3862122 T11983 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:30047/_sd/ya/collection1/ shard1
   [junit4]   2> 3862122 T11983 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
   [junit4]   2> 3862123 T11979 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> 3862124 T11986 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> 3862126 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3862127 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3862230 T11979 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> 3862230 T11986 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> 3862279 T11983 oasc.ZkController.register We are http://127.0.0.1:30047/_sd/ya/collection1/ and leader is http://127.0.0.1:30047/_sd/ya/collection1/
   [junit4]   2> 3862280 T11983 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:30047/_sd/ya
   [junit4]   2> 3862280 T11983 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 3862280 T11983 oasc.ZkController.publish publishing core=collection1 state=active collection=control_collection
   [junit4]   2> 3862280 T11983 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 3862281 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3862282 T11983 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3862282 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3862283 T11976 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:30047/_sd/ya",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:30047__sd%2Fya",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "core_node_name":"core_node1"}
   [junit4]   2> 3862386 T11979 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> 3862386 T11986 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> 3863266 T11953 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 1
   [junit4]   2> 3863267 T11953 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 3863270 T11953 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59459
   [junit4]   2> 3863270 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 3863271 T11953 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 3863271 T11953 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003
   [junit4]   2> 3863271 T11953 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/'
   [junit4]   2> 3863301 T11953 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/solr.xml
   [junit4]   2> 3863351 T11953 oasc.CoreContainer.<init> New CoreContainer 2092249032
   [junit4]   2> 3863352 T11953 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/]
   [junit4]   2> 3863353 T11953 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 3863353 T11953 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: 
   [junit4]   2> 3863353 T11953 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 3863353 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 3863354 T11953 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 3863354 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 3863354 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 3863354 T11953 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 3863355 T11953 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 3863355 T11953 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
   [junit4]   2> 3863355 T11953 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 3863356 T11953 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 3863356 T11953 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 3863356 T11953 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53895/solr
   [junit4]   2> 3863356 T11953 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 3863357 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3863358 T11997 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b54336e name:ZooKeeperConnection Watcher:127.0.0.1:53895 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3863359 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3863362 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3863362 T11999 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15e4cea6 name:ZooKeeperConnection Watcher:127.0.0.1:53895/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3863363 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3863367 T11953 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 3864370 T11953 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59459__sd%2Fya
   [junit4]   2> 3864371 T11953 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59459__sd%2Fya
   [junit4]   2> 3864374 T11979 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 3864375 T12000 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 3864374 T11986 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 3864382 T12001 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
   [junit4]   2> 3864382 T12001 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 3864383 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3864383 T12001 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 3864384 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3864385 T11976 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:59459/_sd/ya",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:59459__sd%2Fya",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 3864385 T11976 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
   [junit4]   2> 3864385 T11976 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
   [junit4]   2> 3864387 T11986 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> 3864387 T12000 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> 3864387 T11979 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> 3865384 T12001 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 3865385 T12001 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 3865385 T12001 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 3865386 T12001 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 3865386 T12001 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 3865387 T12001 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/collection1/'
   [junit4]   2> 3865389 T12001 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/collection1/lib/README' to classloader
   [junit4]   2> 3865389 T12001 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/collection1/lib/classes/' to classloader
   [junit4]   2> 3865390 T12001 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/collection1/lib/.svn/' to classloader
   [junit4]   2> 3865466 T12001 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10
   [junit4]   2> 3865509 T12001 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 3865611 T12001 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 3865620 T12001 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 3865984 T12001 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 3865987 T12001 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 3865989 T12001 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3865993 T12001 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3866010 T12001 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1
   [junit4]   2> 3866010 T12001 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 3866011 T12001 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-003/collection1/, dataDir=./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty1/
   [junit4]   2> 3866011 T12001 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@290f6b0c
   [junit4]   2> 3866013 T12001 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty1
   [junit4]   2> 3866014 T12001 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty1/index/
   [junit4]   2> 3866014 T12001 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty1/index' doesn't exist. Creating new index...
   [junit4]   2> 3866017 T12001 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty1/index
   [junit4]   2> 3866017 T12001 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=6, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
   [junit4]   2> 3866020 T12001 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirectoryWrapper(SimpleFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/index-SimpleFSDirectory-002 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@3081f390),segFN=segments_1,generation=1}
   [junit4]   2> 3866020 T12001 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3866023 T12001 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 3866024 T12001 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 3866024 T12001 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 3866024 T12001 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 3866025 T12001 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 3866025 T12001 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 3866025 T12001 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 3866026 T12001 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 3866026 T12001 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 3866027 T12001 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3866027 T12001 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3866027 T12001 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3866028 T12001 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3866028 T12001 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 3866029 T12001 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 3866029 T12001 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 3866029 T12001 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 3866030 T12001 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3866030 T12001 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 3866030 T12001 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 3866031 T12001 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 3866050 T12001 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3866052 T12001 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3866054 T12001 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3866056 T12001 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3866057 T12001 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3866062 T12001 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 3866062 T12001 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 3866064 T12001 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1470702014, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
   [junit4]   2> 3866066 T12001 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirectoryWrapper(SimpleFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/index-SimpleFSDirectory-002 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@3081f390),segFN=segments_1,generation=1}
   [junit4]   2> 3866066 T12001 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3866066 T12001 oass.SolrIndexSearcher.<init> Opening Searcher@39d3be2b[collection1] main
   [junit4]   2> 3866067 T12001 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 3866068 T12001 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 3866068 T12001 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
   [junit4]   2> 3866068 T12001 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
   [junit4]   2> 3866068 T12001 oasr.RestManager.init Initializing RestManager with initArgs: {}
   [junit4]   2> 3866069 T12001 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3866069 T12001 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json
   [junit4]   2> 3866070 T12001 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3866070 T12001 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
   [junit4]   2> 3866070 T12001 oasr.RestManager.init Initializing 0 registered ManagedResources
   [junit4]   2> 3866073 T12002 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@39d3be2b[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 3866076 T12001 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 3866077 T12005 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59459/_sd/ya collection:collection1 shard:shard3
   [junit4]   2> 3866077 T11953 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1
   [junit4]   2> 3866077 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 3866077 T12005 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
   [junit4]   2> 3866082 T12005 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard3
   [junit4]   2> 3866083 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3866083 T12005 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 3866084 T12005 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C11447 name=collection1 org.apache.solr.core.SolrCore@828538d url=http://127.0.0.1:59459/_sd/ya/collection1 node=127.0.0.1:59459__sd%2Fya C11447_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:59459/_sd/ya, core=collection1, node_name=127.0.0.1:59459__sd%2Fya}
   [junit4]   2> 3866084 T12005 C11447 P59459 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59459/_sd/ya/collection1/
   [junit4]   2> 3866084 T12005 C11447 P59459 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 3866084 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3866084 T12005 C11447 P59459 oasc.SyncStrategy.syncToMe http://127.0.0.1:59459/_sd/ya/collection1/ has no replicas
   [junit4]   2> 3866085 T12005 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59459/_sd/ya/collection1/ shard3
   [junit4]   2> 3866085 T12005 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
   [junit4]   2> 3866087 T12000 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> 3866087 T11986 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> 3866087 T11979 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> 3866089 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3866090 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3866193 T11979 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> 3866193 T12000 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> 3866193 T11986 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> 3866242 T12005 oasc.ZkController.register We are http://127.0.0.1:59459/_sd/ya/collection1/ and leader is http://127.0.0.1:59459/_sd/ya/collection1/
   [junit4]   2> 3866242 T12005 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59459/_sd/ya
   [junit4]   2> 3866242 T12005 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 3866242 T12005 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
   [junit4]   2> 3866242 T12005 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 3866243 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3866244 T12005 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3866244 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3866245 T11976 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:59459/_sd/ya",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:59459__sd%2Fya",
   [junit4]   2> 	  "shard":"shard3",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "core_node_name":"core_node1"}
   [junit4]   2> 3866348 T11979 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> 3866348 T11986 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> 3866348 T12000 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> 3867236 T11953 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 2
   [junit4]   2> 3867237 T11953 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 3867240 T11953 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:26648
   [junit4]   2> 3867241 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 3867241 T11953 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 3867241 T11953 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004
   [junit4]   2> 3867241 T11953 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/'
   [junit4]   2> 3867271 T11953 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/solr.xml
   [junit4]   2> 3867321 T11953 oasc.CoreContainer.<init> New CoreContainer 2035010764
   [junit4]   2> 3867322 T11953 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/]
   [junit4]   2> 3867323 T11953 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
   [junit4]   2> 3867323 T11953 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: 
   [junit4]   2> 3867323 T11953 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 3867323 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 3867324 T11953 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 3867324 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 3867324 T11953 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 3867324 T11953 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 3867324 T11953 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 3867325 T11953 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
   [junit4]   2> 3867325 T11953 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
   [junit4]   2> 3867325 T11953 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
   [junit4]   2> 3867326 T11953 oasc.CoreContainer.load Host Name: 127.0.0.1
   [junit4]   2> 3867326 T11953 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53895/solr
   [junit4]   2> 3867326 T11953 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 3867327 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3867328 T12016 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f72a34a name:ZooKeeperConnection Watcher:127.0.0.1:53895 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3867329 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3867331 T11953 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 3867332 T12018 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10a1c58f name:ZooKeeperConnection Watcher:127.0.0.1:53895/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 3867332 T11953 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 3867337 T11953 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 3868339 T11953 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26648__sd%2Fya
   [junit4]   2> 3868340 T11953 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:26648__sd%2Fya
   [junit4]   2> 3868343 T11979 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 3868343 T12019 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 3868343 T12000 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 3868343 T11986 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 3868350 T12020 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
   [junit4]   2> 3868350 T12020 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 3868351 T12020 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 3868351 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3868352 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3868353 T11976 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:26648/_sd/ya",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:26648__sd%2Fya",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "core_node_name":null}
   [junit4]   2> 3868353 T11976 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
   [junit4]   2> 3868353 T11976 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 3868355 T12000 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> 3868355 T11986 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> 3868355 T12019 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> 3868355 T11979 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> 3869351 T12020 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 3869352 T12020 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 3869353 T12020 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 3869353 T12020 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 3869353 T12020 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 3869354 T12020 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/collection1/'
   [junit4]   2> 3869356 T12020 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/collection1/lib/README' to classloader
   [junit4]   2> 3869357 T12020 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/collection1/lib/.svn/' to classloader
   [junit4]   2> 3869357 T12020 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/collection1/lib/classes/' to classloader
   [junit4]   2> 3869420 T12020 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_4_10
   [junit4]   2> 3869465 T12020 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 3869566 T12020 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 3869575 T12020 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 3869942 T12020 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 3869945 T12020 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 3869947 T12020 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3869951 T12020 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 3869967 T12020 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1
   [junit4]   2> 3869968 T12020 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 3869968 T12020 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../../../usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-004/collection1/, dataDir=./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty2/
   [junit4]   2> 3869968 T12020 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@290f6b0c
   [junit4]   2> 3869972 T12020 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty2
   [junit4]   2> 3869973 T12020 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty2/index/
   [junit4]   2> 3869973 T12020 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty2/index' doesn't exist. Creating new index...
   [junit4]   2> 3869975 T12020 oasc.CachingDirectoryFactory.get return new directory for ./solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/tempDir-001/jetty2/index
   [junit4]   2> 3869975 T12020 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=6, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
   [junit4]   2> 3869978 T12020 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirectoryWrapper(SimpleFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/index-SimpleFSDirectory-003 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@462a284f),segFN=segments_1,generation=1}
   [junit4]   2> 3869978 T12020 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3869982 T12020 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "nodistrib"
   [junit4]   2> 3869982 T12020 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "dedupe"
   [junit4]   2> 3869982 T12020 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 3869983 T12020 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "stored_sig"
   [junit4]   2> 3869983 T12020 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 3869983 T12020 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
   [junit4]   2> 3869983 T12020 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 3869984 T12020 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 3869984 T12020 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
   [junit4]   2> 3869985 T12020 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3869985 T12020 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3869985 T12020 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3869986 T12020 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3869986 T12020 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 3869987 T12020 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 3869987 T12020 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 3869987 T12020 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 3869988 T12020 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
   [junit4]   2> 3869988 T12020 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 3869988 T12020 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 3869989 T12020 oasc.RequestHandlers.initHandlersFromConfig created /admin/file: solr.admin.ShowFileRequestHandler
   [junit4]   2> 3870008 T12020 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3870010 T12020 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3870011 T12020 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3870013 T12020 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3870015 T12020 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 3870020 T12020 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 3870020 T12020 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 3870021 T12020 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1470702014, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
   [junit4]   2> 3870023 T12020 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirectoryWrapper(SimpleFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1/solr.cloud.FullSolrCloudDistribCmdsTest-2F90961CE3B07E66-001/index-SimpleFSDirectory-003 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@462a284f),segFN=segments_1,generation=1}
   [junit4]   2> 3870023 T12020 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 3870023 T12020 oass.SolrIndexSearcher.<init> Opening Searcher@2c589765[collection1] main
   [junit4]   2> 3870024 T12020 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 3870024 T12020 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
   [junit4]   2> 3870025 T12020 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
   [junit4]   2> 3870025 T12020 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
   [junit4]   2> 3870025 T12020 oasr.RestManager.init Initializing RestManager with initArgs: {}
   [junit4]   2> 3870026 T12020 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3870026 T12020 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json
   [junit4]   2> 3870027 T12020 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
   [junit4]   2> 3870027 T12020 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
   [junit4]   2> 3870027 T12020 oasr.RestManager.init Initializing 0 registered ManagedResources
   [junit4]   2> 3870030 T12021 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c589765[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
   [junit4]   2> 3870032 T12020 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 3870033 T12024 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:26648/_sd/ya collection:collection1 shard:shard2
   [junit4]   2> 3870033 T11953 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J1
   [junit4]   2> 3870034 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 3870034 T12024 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 3870038 T12024 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
   [junit4]   2> 3870039 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3870039 T12024 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 3870040 T12024 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> ASYNC  NEW_CORE C11448 name=collection1 org.apache.solr.core.SolrCore@79773203 url=http://127.0.0.1:26648/_sd/ya/collection1 node=127.0.0.1:26648__sd%2Fya C11448_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:26648/_sd/ya, core=collection1, node_name=127.0.0.1:26648__sd%2Fya}
   [junit4]   2> 3870040 T12024 C11448 P26648 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:26648/_sd/ya/collection1/
   [junit4]   2> 3870040 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3870040 T12024 C11448 P26648 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 3870041 T12024 C11448 P26648 oasc.SyncStrategy.syncToMe http://127.0.0.1:26648/_sd/ya/collection1/ has no replicas
   [junit4]   2> 3870041 T12024 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:26648/_sd/ya/collection1/ shard2
   [junit4]   2> 3870041 T12024 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 3870042 T11979 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> 3870042 T11986 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> 3870042 T12019 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> 3870042 T12000 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> 3870045 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3870047 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3870047 T12019 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> 3870048 T11979 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> 3870048 T12000 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> 3870047 T11986 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> 3870095 T12024 oasc.ZkController.register We are http://127.0.0.1:26648/_sd/ya/collection1/ and leader is http://127.0.0.1:26648/_sd/ya/collection1/
   [junit4]   2> 3870096 T12024 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26648/_sd/ya
   [junit4]   2> 3870096 T12024 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 3870096 T12024 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
   [junit4]   2> 3870096 T12024 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 3870097 T11979 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
   [junit4]   2> 3870097 T12024 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3870098 T11976 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 3870099 T11976 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:26648/_sd/ya",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:26648__sd%2Fya",
   [junit4]   2> 	  "shard":"shard2",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "numShards":"3",
   [junit4]   2> 	  "core_node_name":"core_node2"}
   [junit4]   2> 3870202 T12019 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> 3870202 T11979 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> 3870202 T12000 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> 3870202 T11986 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> 3871236 T11953 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 3
   [junit4]   2> 3871237 T11953 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 3871240 T11953 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:14563
   [junit4]   2> 3871240 T11953 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 3871241 T11953 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 3871241 T11953 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../../../usr/home/hudson/hud

[...truncated too long message...]

dPulsing41), 5grand3_s=PostingsFormat(name=Direct), 7grand6_s=PostingsFormat(name=MockRandom), 48parent_f1_s=PostingsFormat(name=Direct), 36parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 4grand2_s=PostingsFormat(name=FSTOrdPulsing41), 7grand4_s=Lucene41(blocksize=128), 44parent_f2_s=Lucene41(blocksize=128), 7grand1_s=PostingsFormat(name=Direct), 2grand1_s=Lucene41(blocksize=128), 16parent_f1_s=Lucene41(blocksize=128), 9parent_f1_s=Lucene41(blocksize=128), 11parent_f2_s=Lucene41(blocksize=128), 23parent_f1_s=PostingsFormat(name=MockRandom), 35parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 3child0_s=Lucene41(blocksize=128), 15parent_f2_s=Lucene41(blocksize=128), 44parent_f1_s=PostingsFormat(name=Direct), 47parent_f1_s=Lucene41(blocksize=128), 3grand2_s=PostingsFormat(name=MockRandom), 4child2_s=PostingsFormat(name=FSTOrdPulsing41), 46parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 24parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 0parent_f1_s=PostingsFormat(name=Direct), 20parent_f2_s=PostingsFormat(name=MockRandom), 7parent_f1_s=PostingsFormat(name=MockRandom), 7grand5_s=PostingsFormat(name=Direct), 48parent_f2_s=Lucene41(blocksize=128), _version_=PostingsFormat(name=FSTOrdPulsing41), 23parent_f2_s=PostingsFormat(name=Direct), 2child0_s=PostingsFormat(name=FSTOrdPulsing41), 16parent_f2_s=PostingsFormat(name=Direct), 21parent_f1_s=Lucene41(blocksize=128), 19parent_f2_s=PostingsFormat(name=MockRandom), 38parent_f2_s=PostingsFormat(name=Direct), 31parent_f2_s=PostingsFormat(name=MockRandom), 51parent_f1_s=PostingsFormat(name=Direct), 5parent_f2_s=PostingsFormat(name=Direct), _root_=PostingsFormat(name=FSTOrdPulsing41), 17parent_f2_s=Lucene41(blocksize=128), 50parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 40parent_f1_s=PostingsFormat(name=Direct), 7grand0_s=Lucene41(blocksize=128), 18parent_f1_s=PostingsFormat(name=MockRandom), 4grand0_s=PostingsFormat(name=Direct), 54parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 28parent_f2_s=Lucene41(blocksize=128), 53parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 6grand4_s=PostingsFormat(name=FSTOrdPulsing41), 22parent_f2_s=Lucene41(blocksize=128), 2grand0_s=PostingsFormat(name=FSTOrdPulsing41), 37parent_f1_s=PostingsFormat(name=Direct), 53parent_f2_s=PostingsFormat(name=MockRandom), 49parent_f2_s=PostingsFormat(name=Direct), 24parent_f2_s=PostingsFormat(name=MockRandom), 33parent_f2_s=Lucene41(blocksize=128), 34parent_f1_s=PostingsFormat(name=MockRandom), 34parent_f2_s=PostingsFormat(name=Direct), 27parent_f2_s=PostingsFormat(name=Direct), 2child1_s=PostingsFormat(name=MockRandom), 3parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 30parent_f1_s=PostingsFormat(name=MockRandom), 39parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 11parent_f1_s=PostingsFormat(name=Direct), 4child3_s=Lucene41(blocksize=128), 4child0_s=PostingsFormat(name=Direct), 49parent_f1_s=PostingsFormat(name=MockRandom), 14parent_f1_s=Lucene41(blocksize=128), 14parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 32parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 41parent_f1_s=PostingsFormat(name=MockRandom), 9parent_f2_s=PostingsFormat(name=Direct), 29parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 19parent_f1_s=PostingsFormat(name=Direct), 2parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 27parent_f1_s=PostingsFormat(name=MockRandom), 54parent_f1_s=Lucene41(blocksize=128), 18parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 1parent_f1_s=Lucene41(blocksize=128), 40parent_f2_s=Lucene41(blocksize=128), 7parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 5grand2_s=Lucene41(blocksize=128), 51parent_f2_s=Lucene41(blocksize=128), 12parent_f2_s=PostingsFormat(name=Direct), 5grand1_s=PostingsFormat(name=FSTOrdPulsing41), 22parent_f1_s=PostingsFormat(name=Direct), 3grand1_s=PostingsFormat(name=Direct), type_s=PostingsFormat(name=FSTOrdPulsing41), 50parent_f1_s=Lucene41(blocksize=128), 13parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 43parent_f1_s=Lucene41(blocksize=128), 6parent_f2_s=Lucene41(blocksize=128), 46parent_f2_s=PostingsFormat(name=MockRandom), 28parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 1grand0_s=Lucene41(blocksize=128), 4parent_f1_s=PostingsFormat(name=Direct), 8parent_f2_s=PostingsFormat(name=MockRandom), 3parent_f1_s=PostingsFormat(name=MockRandom), 31parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 4child1_s=PostingsFormat(name=MockRandom), 42parent_f2_s=PostingsFormat(name=MockRandom), 38parent_f1_s=PostingsFormat(name=MockRandom), 6parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 30parent_f2_s=PostingsFormat(name=Direct), 6grand0_s=PostingsFormat(name=FSTOrdPulsing41), 5grand4_s=PostingsFormat(name=MockRandom), 4grand3_s=PostingsFormat(name=MockRandom), 33parent_f1_s=PostingsFormat(name=Direct), 6grand1_s=PostingsFormat(name=MockRandom), 1parent_f2_s=PostingsFormat(name=Direct), 45parent_f1_s=PostingsFormat(name=MockRandom), 29parent_f1_s=PostingsFormat(name=MockRandom), 39parent_f2_s=PostingsFormat(name=MockRandom), 4parent_f2_s=PostingsFormat(name=MockRandom), 32parent_f1_s=Lucene41(blocksize=128), 10parent_f1_s=Lucene41(blocksize=128), 35parent_f2_s=PostingsFormat(name=MockRandom), 37parent_f2_s=Lucene41(blocksize=128), 25parent_f1_s=Lucene41(blocksize=128), 7grand3_s=PostingsFormat(name=FSTOrdPulsing41), 21parent_f2_s=PostingsFormat(name=FSTOrdPulsing41), 36parent_f1_s=Lucene41(blocksize=128), text_t=PostingsFormat(name=FSTOrdPulsing41), 17parent_f1_s=PostingsFormat(name=FSTOrdPulsing41), 13parent_f2_s=PostingsFormat(name=MockRandom), 3child2_s=PostingsFormat(name=MockRandom), 4grand1_s=Lucene41(blocksize=128), rnd_b=PostingsFormat(name=MockRandom)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=en_IN, timezone=Antarctica/Syowa
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=211459184,total=477102080
   [junit4]   2> NOTE: All tests run in this JVM: [TestBadConfig, SampleTest, TestCursorMarkWithoutUniqueKey, HdfsRecoveryZkTest, DistributedQueryElevationComponentTest, TermVectorComponentDistributedTest, TestMultiCoreConfBootstrap, SSLMigrationTest, TestDynamicFieldCollectionResource, TestMissingGroups, TestNoOpRegenerator, HttpPartitionTest, DistributedSuggestComponentTest, CacheHeaderTest, TestSweetSpotSimilarityFactory, TestElisionMultitermQuery, AutoCommitTest, TestWriterPerf, SearchHandlerTest, TestFiltering, SOLR749Test, SuggesterFSTTest, TestLMDirichletSimilarityFactory, TestDistributedGrouping, TestUpdate, TestSolrQueryParser, TestManagedSchemaFieldResource, MultiTermTest, HardAutoCommitTest, AnalysisErrorHandlingTest, SoftAutoCommitTest, TestFastWriter, DistributedQueryComponentCustomSortTest, ChaosMonkeyNothingIsSafeTest, LukeRequestHandlerTest, TestPseudoReturnFields, OpenCloseCoreStressTest, DocValuesTest, CircularListTest, LegacyHTMLStripCharFilterTest, DistributedQueryComponentOptimizationTest, BasicDistributedZk2Test, RequestHandlersTest, DocValuesMissingTest, TestDocBasedVersionConstraints, TestQueryUtils, TestValueSourceCache, TestIndexingPerformance, DefaultValueUpdateProcessorTest, TestCSVResponseWriter, ResponseHeaderTest, TestReversedWildcardFilterFactory, CopyFieldTest, ClusterStateTest, HdfsLockFactoryTest, TestRecoveryHdfs, TestCollationFieldDocValues, AddBlockUpdateTest, DOMUtilTest, TestImplicitCoreProperties, BinaryUpdateRequestHandlerTest, TestSolr4Spatial2, TestSystemIdResolver, TestFieldCollectionResource, TestGroupingSearch, TestFastLRUCache, TestInfoStreamLogging, QueryParsingTest, InfoHandlerTest, ZkSolrClientTest, AnalyticsMergeStrategyTest, TestJoin, UniqFieldsUpdateProcessorFactoryTest, TestPerFieldSimilarity, OutputWriterTest, TestPHPSerializedResponseWriter, DirectUpdateHandlerOptimizeTest, TimeZoneUtilsTest, PrimUtilsTest, TestConfigSets, TestIndexSearcher, TestFieldSortValues, ShardSplitTest, DocExpirationUpdateProcessorFactoryTest, TestSerializedLuceneMatchVersion, CoreContainerCoreInitFailuresTest, DeleteReplicaTest, TestStressLucene, EnumFieldTest, TestRandomFaceting, TestCloudInspectUtil, TestAtomicUpdateErrorCases, DistributedTermsComponentTest, TestBlendedInfixSuggestions, TestZkChroot, ChaosMonkeySafeLeaderTest, CollectionsAPIDistributedZkTest, SyncSliceTest, LeaderElectionIntegrationTest, BasicZkTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest]
   [junit4] Completed on J1 in 141.49s, 1 test, 1 error <<< FAILURES!

[...truncated 650 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:481: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:454: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:45: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/common-build.xml:496: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1299: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:923: There were test failures: 410 suites, 1711 tests, 1 error, 50 ignored (8 assumptions)

Total time: 286 minutes 41 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-NightlyTests-4.x #586
Archived 3 artifacts
Archive block size is 32768
Received 0 blocks and 461190114 bytes
Compression is 0.0%
Took 1 min 15 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure