You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/08/13 22:51:22 UTC

[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1501 - Failure

Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1501/

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

Error Message:
Java heap space

Stack Trace:
java.lang.OutOfMemoryError: Java heap space




Build Log:
[...truncated 9980 lines...]
   [junit4] Suite: org.apache.solr.cloud.FullSolrCloudDistribCmdsTest
   [junit4]   2> 1038867 T2628 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /jrcn/
   [junit4]   2> 1038874 T2628 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
   [junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solrtest-FullSolrCloudDistribCmdsTest-1376425083743
   [junit4]   2> 1038876 T2628 oasc.ZkTestServer.run STARTING ZK TEST SERVER
   [junit4]   2> 1038876 T2629 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
   [junit4]   2> 1038977 T2628 oasc.ZkTestServer.run start zk server on port:15446
   [junit4]   2> 1038978 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1039008 T2635 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72088542 name:ZooKeeperConnection Watcher:127.0.0.1:15446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1039008 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1039009 T2628 oascc.SolrZkClient.makePath makePath: /solr
   [junit4]   2> 1039022 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1039024 T2637 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2742c9a1 name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1039025 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1039025 T2628 oascc.SolrZkClient.makePath makePath: /collections/collection1
   [junit4]   2> 1039035 T2628 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
   [junit4]   2> 1039038 T2628 oascc.SolrZkClient.makePath makePath: /collections/control_collection
   [junit4]   2> 1039041 T2628 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
   [junit4]   2> 1039044 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
   [junit4]   2> 1039044 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
   [junit4]   2> 1039057 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
   [junit4]   2> 1039057 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
   [junit4]   2> 1039161 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 1039162 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
   [junit4]   2> 1039165 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
   [junit4]   2> 1039166 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
   [junit4]   2> 1039169 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
   [junit4]   2> 1039169 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
   [junit4]   2> 1039172 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
   [junit4]   2> 1039173 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
   [junit4]   2> 1039176 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
   [junit4]   2> 1039177 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
   [junit4]   2> 1039184 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 1039185 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
   [junit4]   2> 1039188 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
   [junit4]   2> 1039188 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
   [junit4]   2> 1039191 T2628 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
   [junit4]   2> 1039192 T2628 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
   [junit4]   2> 1039470 T2628 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1039476 T2628 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:26166
   [junit4]   2> 1039477 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1039477 T2628 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1039478 T2628 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070
   [junit4]   2> 1039478 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/'
   [junit4]   2> 1039519 T2628 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/solr.xml
   [junit4]   2> 1039611 T2628 oasc.CoreContainer.<init> New CoreContainer 991967351
   [junit4]   2> 1039612 T2628 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/]
   [junit4]   2> 1039614 T2628 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1039615 T2628 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1039615 T2628 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1039616 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1039616 T2628 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1039617 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1039617 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1039617 T2628 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1039618 T2628 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1039618 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1039637 T2628 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15446/solr
   [junit4]   2> 1039638 T2628 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1039639 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1039642 T2648 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6dfdd320 name:ZooKeeperConnection Watcher:127.0.0.1:15446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1039642 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1039651 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
   [junit4]   2> 1039665 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1039666 T2650 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13f3ebd1 name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1039667 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1039669 T2628 oascc.SolrZkClient.makePath makePath: /overseer/queue
   [junit4]   2> 1039681 T2628 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
   [junit4]   2> 1039685 T2628 oascc.SolrZkClient.makePath makePath: /live_nodes
   [junit4]   2> 1039687 T2628 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26166_jrcn
   [junit4]   2> 1039694 T2628 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:26166_jrcn
   [junit4]   2> 1039697 T2628 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
   [junit4]   2> 1039715 T2628 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
   [junit4]   2> 1039718 T2628 oasc.Overseer.start Overseer (id=90205394288705539-127.0.0.1:26166_jrcn-n_0000000000) starting
   [junit4]   2> 1039730 T2628 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
   [junit4]   2> 1039742 T2652 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
   [junit4]   2> 1039742 T2628 oascc.SolrZkClient.makePath makePath: /clusterstate.json
   [junit4]   2> 1039744 T2628 oascc.SolrZkClient.makePath makePath: /aliases.json
   [junit4]   2> 1039746 T2628 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1039749 T2651 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
   [junit4]   2> 1039754 T2653 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1039755 T2653 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1039756 T2653 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1041252 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1041254 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:26166_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:26166/jrcn"}
   [junit4]   2> 1041254 T2651 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
   [junit4]   2> 1041254 T2651 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 1041272 T2650 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> 1041758 T2653 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1041758 T2653 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/collection1
   [junit4]   2> 1041758 T2653 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
   [junit4]   2> 1041759 T2653 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1041759 T2653 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
   [junit4]   2> 1041760 T2653 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/collection1/'
   [junit4]   2> 1041762 T2653 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/collection1/lib/README' to classloader
   [junit4]   2> 1041763 T2653 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/collection1/lib/classes/' to classloader
   [junit4]   2> 1041822 T2653 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
   [junit4]   2> 1041885 T2653 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1041987 T2653 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1041999 T2653 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1042667 T2653 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1042669 T2653 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1042670 T2653 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 1042683 T2653 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1042687 T2653 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1042702 T2653 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1042707 T2653 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1042711 T2653 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1042713 T2653 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1042713 T2653 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1042713 T2653 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1042714 T2653 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1042714 T2653 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1042715 T2653 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1042715 T2653 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-controljetty-1376425084070/collection1/, dataDir=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/control/data/
   [junit4]   2> 1042716 T2653 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@38f164ae
   [junit4]   2> 1042717 T2653 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/control/data
   [junit4]   2> 1042717 T2653 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/control/data/index/
   [junit4]   2> 1042717 T2653 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/control/data/index' doesn't exist. Creating new index...
   [junit4]   2> 1042718 T2653 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/control/data/index
   [junit4]   2> 1042723 T2653 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4cf1cc9e lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d865cfe),segFN=segments_1,generation=1}
   [junit4]   2> 1042723 T2653 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1042728 T2653 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1042729 T2653 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1042730 T2653 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1042730 T2653 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1042731 T2653 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1042731 T2653 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1042732 T2653 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1042732 T2653 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1042733 T2653 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1042750 T2653 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1042758 T2653 oass.SolrIndexSearcher.<init> Opening Searcher@2778d6f5 main
   [junit4]   2> 1042759 T2653 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1042759 T2653 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1042763 T2654 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2778d6f5 main{StandardDirectoryReader(segments_1:1)}
   [junit4]   2> 1042765 T2653 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1042766 T2653 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:26166/jrcn collection:control_collection shard:shard1
   [junit4]   2> 1042766 T2653 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
   [junit4]   2> 1042785 T2653 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
   [junit4]   2> 1042802 T2653 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 1042805 T2653 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 1042805 T2653 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> 1042805 T2653 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:26166/jrcn/collection1/
   [junit4]   2> 1042805 T2653 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 1042806 T2653 oasc.SyncStrategy.syncToMe http://127.0.0.1:26166/jrcn/collection1/ has no replicas
   [junit4]   2> 1042806 T2653 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:26166/jrcn/collection1/ shard1
   [junit4]   2> 1042806 T2653 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
   [junit4]   2> 1044278 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1044302 T2650 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> 1044343 T2653 oasc.ZkController.register We are http://127.0.0.1:26166/jrcn/collection1/ and leader is http://127.0.0.1:26166/jrcn/collection1/
   [junit4]   2> 1044343 T2653 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26166/jrcn
   [junit4]   2> 1044343 T2653 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 1044343 T2653 oasc.ZkController.publish publishing core=collection1 state=active
   [junit4]   2> 1044344 T2653 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1044346 T2653 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1044347 T2628 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
   [junit4]   2> 1044347 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1044348 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1044360 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:
   [junit4]   2> 1044362 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1044364 T2657 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ecbca0b name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1044364 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1044366 T2628 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1044368 T2628 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
   [junit4]   2> 1044631 T2628 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1044635 T2628 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:65260
   [junit4]   2> 1044635 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1044636 T2628 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1044636 T2628 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236
   [junit4]   2> 1044637 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/'
   [junit4]   2> 1044677 T2628 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/solr.xml
   [junit4]   2> 1044768 T2628 oasc.CoreContainer.<init> New CoreContainer 379516755
   [junit4]   2> 1044769 T2628 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/]
   [junit4]   2> 1044771 T2628 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1044772 T2628 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1044772 T2628 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1044773 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1044773 T2628 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1044774 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1044774 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1044774 T2628 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1044775 T2628 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1044775 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1044792 T2628 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15446/solr
   [junit4]   2> 1044792 T2628 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1044793 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1044797 T2668 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@785818aa name:ZooKeeperConnection Watcher:127.0.0.1:15446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1044797 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1044813 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
   [junit4]   2> 1044824 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1044826 T2670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@56462efb name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1044827 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1044839 T2628 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1045815 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1045816 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node1",
   [junit4]   2> 	  "numShards":"1",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"control_collection",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:26166_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:26166/jrcn"}
   [junit4]   2> 1045836 T2670 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> 1045836 T2657 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> 1045836 T2650 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> 1045842 T2628 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:65260_jrcn
   [junit4]   2> 1045844 T2628 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:65260_jrcn
   [junit4]   2> 1045846 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
   [junit4]   2> 1045846 T2657 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 1045846 T2650 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 1045846 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1045847 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1045847 T2670 oascc.ZkStateReader$3.process Updating live nodes... (2)
   [junit4]   2> 1045862 T2671 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1045863 T2671 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1045864 T2671 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1047341 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1047342 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:65260_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:65260/jrcn"}
   [junit4]   2> 1047343 T2651 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2]
   [junit4]   2> 1047343 T2651 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 1047360 T2650 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> 1047360 T2670 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> 1047360 T2657 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> 1047866 T2671 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1047866 T2671 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/collection1
   [junit4]   2> 1047866 T2671 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 1047867 T2671 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1047868 T2671 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 1047869 T2671 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/collection1/'
   [junit4]   2> 1047870 T2671 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/collection1/lib/README' to classloader
   [junit4]   2> 1047871 T2671 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/collection1/lib/classes/' to classloader
   [junit4]   2> 1047933 T2671 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
   [junit4]   2> 1047998 T2671 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1048100 T2671 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1048112 T2671 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1048802 T2671 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1048803 T2671 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1048804 T2671 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 1048817 T2671 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1048822 T2671 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1048836 T2671 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1048841 T2671 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1048846 T2671 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1048847 T2671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1048847 T2671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1048847 T2671 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1048848 T2671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1048849 T2671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1048849 T2671 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1048849 T2671 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty1-1376425089236/collection1/, dataDir=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty1/
   [junit4]   2> 1048850 T2671 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@38f164ae
   [junit4]   2> 1048851 T2671 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty1
   [junit4]   2> 1048851 T2671 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty1/index/
   [junit4]   2> 1048852 T2671 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty1/index' doesn't exist. Creating new index...
   [junit4]   2> 1048852 T2671 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty1/index
   [junit4]   2> 1048856 T2671 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@446d2a49 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26d4f411),segFN=segments_1,generation=1}
   [junit4]   2> 1048856 T2671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1048863 T2671 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1048863 T2671 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1048864 T2671 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1048865 T2671 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1048866 T2671 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1048866 T2671 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1048866 T2671 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1048867 T2671 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1048868 T2671 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1048884 T2671 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1048891 T2671 oass.SolrIndexSearcher.<init> Opening Searcher@55f193e6 main
   [junit4]   2> 1048893 T2671 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1048893 T2671 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1048899 T2672 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55f193e6 main{StandardDirectoryReader(segments_1:1)}
   [junit4]   2> 1048902 T2671 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1048902 T2671 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:65260/jrcn collection:collection1 shard:shard1
   [junit4]   2> 1048902 T2671 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
   [junit4]   2> 1048920 T2671 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
   [junit4]   2> 1048949 T2671 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
   [junit4]   2> 1048953 T2671 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 1048953 T2671 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> 1048953 T2671 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:65260/jrcn/collection1/
   [junit4]   2> 1048953 T2671 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 1048954 T2671 oasc.SyncStrategy.syncToMe http://127.0.0.1:65260/jrcn/collection1/ has no replicas
   [junit4]   2> 1048954 T2671 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:65260/jrcn/collection1/ shard1
   [junit4]   2> 1048954 T2671 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
   [junit4]   2> 1050366 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1050390 T2657 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> 1050390 T2670 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> 1050390 T2650 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> 1050396 T2671 oasc.ZkController.register We are http://127.0.0.1:65260/jrcn/collection1/ and leader is http://127.0.0.1:65260/jrcn/collection1/
   [junit4]   2> 1050396 T2671 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:65260/jrcn
   [junit4]   2> 1050396 T2671 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 1050396 T2671 oasc.ZkController.publish publishing core=collection1 state=active
   [junit4]   2> 1050397 T2671 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1050398 T2671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1050399 T2628 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
   [junit4]   2> 1050400 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1050401 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1050675 T2628 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1050679 T2628 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:25259
   [junit4]   2> 1050680 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1050680 T2628 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1050681 T2628 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281
   [junit4]   2> 1050681 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/'
   [junit4]   2> 1050723 T2628 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/solr.xml
   [junit4]   2> 1050816 T2628 oasc.CoreContainer.<init> New CoreContainer 141757050
   [junit4]   2> 1050816 T2628 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/]
   [junit4]   2> 1050818 T2628 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1050819 T2628 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1050819 T2628 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1050820 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1050820 T2628 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1050821 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1050821 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1050822 T2628 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1050822 T2628 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1050823 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1050841 T2628 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15446/solr
   [junit4]   2> 1050841 T2628 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1050842 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1050845 T2684 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@38264127 name:ZooKeeperConnection Watcher:127.0.0.1:15446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1050846 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1050863 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
   [junit4]   2> 1050876 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1050878 T2686 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@efdb834 name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1050878 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1050887 T2628 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1051890 T2628 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:25259_jrcn
   [junit4]   2> 1051892 T2628 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:25259_jrcn
   [junit4]   2> 1051895 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
   [junit4]   2> 1051895 T2657 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1051895 T2686 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1051895 T2650 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1051895 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1051896 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1051897 T2670 oascc.ZkStateReader$3.process Updating live nodes... (3)
   [junit4]   2> 1051906 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1051907 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node1",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:65260_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:65260/jrcn"}
   [junit4]   2> 1051913 T2687 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1051913 T2687 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1051916 T2687 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1051917 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node2",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:25259_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:25259/jrcn"}
   [junit4]   2> 1051917 T2651 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
   [junit4]   2> 1051917 T2651 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
   [junit4]   2> 1051931 T2657 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> 1051931 T2686 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> 1051931 T2670 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> 1051936 T2650 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> 1052917 T2687 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1052917 T2687 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/collection1
   [junit4]   2> 1052917 T2687 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 1052918 T2687 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1052918 T2687 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 1052919 T2687 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/collection1/'
   [junit4]   2> 1052921 T2687 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/collection1/lib/classes/' to classloader
   [junit4]   2> 1052921 T2687 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/collection1/lib/README' to classloader
   [junit4]   2> 1052983 T2687 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
   [junit4]   2> 1053047 T2687 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1053148 T2687 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1053160 T2687 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1053819 T2687 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1053819 T2687 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1053820 T2687 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 1053833 T2687 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1053837 T2687 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1053851 T2687 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1053856 T2687 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1053861 T2687 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1053862 T2687 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1053862 T2687 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1053862 T2687 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1053863 T2687 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1053864 T2687 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1053864 T2687 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1053865 T2687 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty2-1376425095281/collection1/, dataDir=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty2/
   [junit4]   2> 1053865 T2687 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@38f164ae
   [junit4]   2> 1053866 T2687 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty2
   [junit4]   2> 1053866 T2687 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty2/index/
   [junit4]   2> 1053866 T2687 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty2/index' doesn't exist. Creating new index...
   [junit4]   2> 1053867 T2687 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty2/index
   [junit4]   2> 1053871 T2687 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@87bad40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2865c976),segFN=segments_1,generation=1}
   [junit4]   2> 1053871 T2687 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1053877 T2687 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1053878 T2687 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1053878 T2687 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1053879 T2687 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1053880 T2687 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1053880 T2687 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1053881 T2687 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1053882 T2687 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1053882 T2687 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1053898 T2687 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1053906 T2687 oass.SolrIndexSearcher.<init> Opening Searcher@270d41e4 main
   [junit4]   2> 1053907 T2687 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1053907 T2687 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1053913 T2688 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@270d41e4 main{StandardDirectoryReader(segments_1:1)}
   [junit4]   2> 1053916 T2687 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1053916 T2687 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:25259/jrcn collection:collection1 shard:shard2
   [junit4]   2> 1053916 T2687 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
   [junit4]   2> 1053935 T2687 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
   [junit4]   2> 1053953 T2687 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
   [junit4]   2> 1053956 T2687 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
   [junit4]   2> 1053956 T2687 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
   [junit4]   2> 1053956 T2687 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:25259/jrcn/collection1/
   [junit4]   2> 1053957 T2687 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
   [junit4]   2> 1053957 T2687 oasc.SyncStrategy.syncToMe http://127.0.0.1:25259/jrcn/collection1/ has no replicas
   [junit4]   2> 1053957 T2687 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:25259/jrcn/collection1/ shard2
   [junit4]   2> 1053957 T2687 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
   [junit4]   2> 1054939 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1054964 T2650 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> 1054964 T2686 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> 1054964 T2657 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> 1054964 T2670 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> 1054982 T2687 oasc.ZkController.register We are http://127.0.0.1:25259/jrcn/collection1/ and leader is http://127.0.0.1:25259/jrcn/collection1/
   [junit4]   2> 1054982 T2687 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:25259/jrcn
   [junit4]   2> 1054982 T2687 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
   [junit4]   2> 1054982 T2687 oasc.ZkController.publish publishing core=collection1 state=active
   [junit4]   2> 1054983 T2687 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1054984 T2687 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1054985 T2628 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
   [junit4]   2> 1054986 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1054987 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1055260 T2628 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1055264 T2628 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:14062
   [junit4]   2> 1055265 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1055265 T2628 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1055266 T2628 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868
   [junit4]   2> 1055266 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/'
   [junit4]   2> 1055306 T2628 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/solr.xml
   [junit4]   2> 1055397 T2628 oasc.CoreContainer.<init> New CoreContainer 1841595451
   [junit4]   2> 1055398 T2628 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/]
   [junit4]   2> 1055399 T2628 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1055400 T2628 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1055400 T2628 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1055401 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1055401 T2628 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1055402 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1055402 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1055403 T2628 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1055403 T2628 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1055404 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1055422 T2628 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15446/solr
   [junit4]   2> 1055422 T2628 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1055423 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1055426 T2700 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d89a05f name:ZooKeeperConnection Watcher:127.0.0.1:15446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1055427 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1055429 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
   [junit4]   2> 1055442 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1055444 T2702 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b6a0475 name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1055444 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1055456 T2628 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1056459 T2628 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:14062_jrcn
   [junit4]   2> 1056470 T2628 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:14062_jrcn
   [junit4]   2> 1056472 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1056473 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
   [junit4]   2> 1056473 T2657 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1056473 T2702 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1056474 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node2",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "shard":"shard2",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"active",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:25259_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:25259/jrcn"}
   [junit4]   2> 1056473 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056473 T2686 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1056474 T2670 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1056474 T2686 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056493 T2703 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1056494 T2703 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1056497 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056497 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056497 T2702 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056497 T2686 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056498 T2703 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1056501 T2650 oascc.ZkStateReader$3.process Updating live nodes... (4)
   [junit4]   2> 1056501 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1056502 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1058002 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1058004 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node3",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "shard":null,
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"down",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:14062_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:14062/jrcn"}
   [junit4]   2> 1058004 T2651 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
   [junit4]   2> 1058004 T2651 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
   [junit4]   2> 1058019 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1058019 T2702 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1058019 T2686 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1058019 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1058019 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1058501 T2703 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
   [junit4]   2> 1058501 T2703 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/collection1
   [junit4]   2> 1058501 T2703 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
   [junit4]   2> 1058502 T2703 oasc.ZkController.createCollectionZkNode Collection zkNode exists
   [junit4]   2> 1058503 T2703 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
   [junit4]   2> 1058504 T2703 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/collection1/'
   [junit4]   2> 1058505 T2703 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/collection1/lib/README' to classloader
   [junit4]   2> 1058506 T2703 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/collection1/lib/classes/' to classloader
   [junit4]   2> 1058567 T2703 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_45
   [junit4]   2> 1058631 T2703 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
   [junit4]   2> 1058732 T2703 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
   [junit4]   2> 1058744 T2703 oass.IndexSchema.readSchema [collection1] Schema name=test
   [junit4]   2> 1059399 T2703 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1059400 T2703 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
   [junit4]   2> 1059401 T2703 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
   [junit4]   2> 1059414 T2703 oass.IndexSchema.readSchema default search field in schema is text
   [junit4]   2> 1059418 T2703 oass.IndexSchema.readSchema unique key field: id
   [junit4]   2> 1059432 T2703 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1059437 T2703 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
   [junit4]   2> 1059442 T2703 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1059443 T2703 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1059443 T2703 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1059443 T2703 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
   [junit4]   2> 1059444 T2703 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
   [junit4]   2> 1059445 T2703 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
   [junit4]   2> 1059445 T2703 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
   [junit4]   2> 1059445 T2703 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty3-1376425099868/collection1/, dataDir=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty3/
   [junit4]   2> 1059446 T2703 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@38f164ae
   [junit4]   2> 1059447 T2703 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty3
   [junit4]   2> 1059447 T2703 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty3/index/
   [junit4]   2> 1059447 T2703 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty3/index' doesn't exist. Creating new index...
   [junit4]   2> 1059448 T2703 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-1376425083742/jetty3/index
   [junit4]   2> 1059452 T2703 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
   [junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@157775f lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d4489ea),segFN=segments_1,generation=1}
   [junit4]   2> 1059452 T2703 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
   [junit4]   2> 1059458 T2703 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
   [junit4]   2> 1059458 T2703 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
   [junit4]   2> 1059459 T2703 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
   [junit4]   2> 1059460 T2703 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
   [junit4]   2> 1059461 T2703 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
   [junit4]   2> 1059461 T2703 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
   [junit4]   2> 1059461 T2703 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
   [junit4]   2> 1059462 T2703 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
   [junit4]   2> 1059463 T2703 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
   [junit4]   2> 1059479 T2703 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
   [junit4]   2> 1059487 T2703 oass.SolrIndexSearcher.<init> Opening Searcher@1086376f main
   [junit4]   2> 1059488 T2703 oasu.CommitTracker.<init> Hard AutoCommit: disabled
   [junit4]   2> 1059488 T2703 oasu.CommitTracker.<init> Soft AutoCommit: disabled
   [junit4]   2> 1059494 T2704 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1086376f main{StandardDirectoryReader(segments_1:1)}
   [junit4]   2> 1059497 T2703 oasc.CoreContainer.registerCore registering core: collection1
   [junit4]   2> 1059497 T2703 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:14062/jrcn collection:collection1 shard:shard1
   [junit4]   2> 1059497 T2703 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=15000&socketTimeout=30000&retry=false
   [junit4]   2> 1059541 T2703 oasc.ZkController.register We are http://127.0.0.1:14062/jrcn/collection1/ and leader is http://127.0.0.1:65260/jrcn/collection1/
   [junit4]   2> 1059542 T2703 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:14062/jrcn
   [junit4]   2> 1059542 T2703 oasc.ZkController.checkRecovery Core needs to recover:collection1
   [junit4]   2> 1059542 T2703 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
   [junit4]   2> ASYNC  NEW_CORE C1657 name=collection1 org.apache.solr.core.SolrCore@3bc3de07 url=http://127.0.0.1:14062/jrcn/collection1 node=127.0.0.1:14062_jrcn C1657_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:14062_jrcn, base_url=http://127.0.0.1:14062/jrcn}
   [junit4]   2> 1059543 T2705 C1657 P14062 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
   [junit4]   2> 1059543 T2703 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1059544 T2705 C1657 P14062 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
   [junit4]   2> 1059544 T2705 C1657 P14062 oasc.ZkController.publish publishing core=collection1 state=recovering
   [junit4]   2> 1059544 T2705 C1657 P14062 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1059545 T2628 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
   [junit4]   2> 1059545 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
   [junit4]   2> 1059546 T2705 C1657 P14062 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1059546 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
   [junit4]   2> 1059559 T2660 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
   [junit4]   2> 1059824 T2628 oejs.Server.doStart jetty-8.1.10.v20130312
   [junit4]   2> 1059827 T2628 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:28394
   [junit4]   2> 1059827 T2628 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
   [junit4]   2> 1059828 T2628 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
   [junit4]   2> 1059828 T2628 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty4-1376425104425
   [junit4]   2> 1059829 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty4-1376425104425/'
   [junit4]   2> 1059869 T2628 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty4-1376425104425/solr.xml
   [junit4]   2> 1059959 T2628 oasc.CoreContainer.<init> New CoreContainer 1661238232
   [junit4]   2> 1059960 T2628 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.FullSolrCloudDistribCmdsTest-jetty4-1376425104425/]
   [junit4]   2> 1059962 T2628 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
   [junit4]   2> 1059962 T2628 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
   [junit4]   2> 1059963 T2628 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
   [junit4]   2> 1059963 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
   [junit4]   2> 1059964 T2628 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
   [junit4]   2> 1059964 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
   [junit4]   2> 1059965 T2628 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
   [junit4]   2> 1059965 T2628 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
   [junit4]   2> 1059965 T2628 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
   [junit4]   2> 1059966 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
   [junit4]   2> 1059982 T2628 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15446/solr
   [junit4]   2> 1059982 T2628 oasc.ZkController.checkChrootPath zkHost includes chroot
   [junit4]   2> 1059983 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1059986 T2717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@443b8d19 name:ZooKeeperConnection Watcher:127.0.0.1:15446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1059987 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1060002 T2628 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
   [junit4]   2> 1060012 T2628 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
   [junit4]   2> 1060014 T2719 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36e8a04a name:ZooKeeperConnection Watcher:127.0.0.1:15446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
   [junit4]   2> 1060014 T2628 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
   [junit4]   2> 1060027 T2628 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
   [junit4]   2> 1061030 T2628 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:28394_jrcn
   [junit4]   2> 1061042 T2628 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:28394_jrcn
   [junit4]   2> 1061043 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
   [junit4]   2> 1061044 T2702 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1061044 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
   [junit4]   2> 1061045 T2657 oascc.ZkStateReader$3.process Updating live nodes... (5)
   [junit4]   2> 1061045 T2719 oascc.ZkStateReader$3.process Updating live nodes... (5)
   [junit4]   2> 1061045 T2686 oascc.ZkStateReader$3.process Updating live nodes... (5)
   [junit4]   2> 1061045 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061045 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
   [junit4]   2> 	  "operation":"state",
   [junit4]   2> 	  "core_node_name":"core_node3",
   [junit4]   2> 	  "numShards":"2",
   [junit4]   2> 	  "shard":"shard1",
   [junit4]   2> 	  "roles":null,
   [junit4]   2> 	  "state":"recovering",
   [junit4]   2> 	  "shard_state":"active",
   [junit4]   2> 	  "core":"collection1",
   [junit4]   2> 	  "collection":"collection1",
   [junit4]   2> 	  "shard_range":null,
   [junit4]   2> 	  "node_name":"127.0.0.1:14062_jrcn",
   [junit4]   2> 	  "base_url":"http://127.0.0.1:14062/jrcn"}
   [junit4]   2> 1061045 T2686 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061046 T2702 oascc.ZkStateReader$3.process Updating live nodes... (5)
   [junit4]   2> 1061057 T2670 oascc.ZkStateReader$3.process Updating live nodes... (5)
   [junit4]   2> 1061065 T2720 oasc.ZkController.publish publishing core=collection1 state=down
   [junit4]   2> 1061065 T2720 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
   [junit4]   2> 1061070 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061070 T2702 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061070 T2686 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061070 T2670 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061070 T2657 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061072 T2720 oasc.ZkController.waitForCoreNodeName look for our core node name
   [junit4]   2> 1061075 T2650 oascc.ZkStateReader$3.process Updating live nodes... (5)
   [junit4]   2> 1061075 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061076 T2650 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
   [junit4]   2> 1061

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

_s=PostingsFormat(name=NestedPulsing), 14grand9_s=PostingsFormat(name=SimpleText), 61grand3_s=PostingsFormat(name=NestedPulsing), 83grand20_s=Lucene41(blocksize=128), 50grand18_s=PostingsFormat(name=NestedPulsing), 83grand8_s=Lucene41(blocksize=128), 67grand15_s=Lucene41(blocksize=128), 71grand25_s=PostingsFormat(name=Asserting), 79grand64_s=PostingsFormat(name=NestedPulsing), 77grand36_s=Lucene41(blocksize=128), 55grand21_s=Lucene41(blocksize=128), 22child12_s=PostingsFormat(name=Asserting), 30grand29_s=PostingsFormat(name=SimpleText), 43grand17_s=Lucene41(blocksize=128), 74grand63_s=PostingsFormat(name=NestedPulsing), 58grand50_s=PostingsFormat(name=SimpleText), 43child21_s=PostingsFormat(name=SimpleText), 53grand27_s=Lucene41(blocksize=128), 17grand15_s=PostingsFormat(name=NestedPulsing), 33grand6_s=PostingsFormat(name=SimpleText), 75grand25_s=PostingsFormat(name=Asserting), 32grand16_s=PostingsFormat(name=SimpleText), 24grand9_s=Lucene41(blocksize=128), 53grand38_s=Lucene41(blocksize=128), 0parent_f1_s=PostingsFormat(name=SimpleText), 40child39_s=PostingsFormat(name=SimpleText), 78grand39_s=PostingsFormat(name=Asserting), 34grand26_s=Lucene41(blocksize=128), 37child10_s=Lucene41(blocksize=128), 68grand40_s=PostingsFormat(name=NestedPulsing), 59grand0_s=PostingsFormat(name=SimpleText), 80grand38_s=PostingsFormat(name=Asserting), 63grand24_s=PostingsFormat(name=Asserting), 83grand31_s=Lucene41(blocksize=128), 85grand73_s=Lucene41(blocksize=128), 52grand18_s=PostingsFormat(name=SimpleText), 64grand7_s=PostingsFormat(name=Asserting), 9grand2_s=Lucene41(blocksize=128), 20grand5_s=Lucene41(blocksize=128), 23child6_s=Lucene41(blocksize=128), 29child18_s=PostingsFormat(name=NestedPulsing), 85grand66_s=Lucene41(blocksize=128), 76grand74_s=PostingsFormat(name=SimpleText), 72grand65_s=PostingsFormat(name=NestedPulsing), 38child33_s=Lucene41(blocksize=128), 82grand32_s=PostingsFormat(name=Asserting), 40grand18_s=Lucene41(blocksize=128), 77grand21_s=Lucene41(blocksize=128), 71grand19_s=PostingsFormat(name=SimpleText), 65grand36_s=PostingsFormat(name=SimpleText), 34child16_s=PostingsFormat(name=NestedPulsing), 73grand40_s=PostingsFormat(name=NestedPulsing), 64grand48_s=PostingsFormat(name=NestedPulsing), 26child13_s=PostingsFormat(name=NestedPulsing), 35grand34_s=Lucene41(blocksize=128), 65grand42_s=Lucene41(blocksize=128), 64grand53_s=PostingsFormat(name=SimpleText), 39grand10_s=PostingsFormat(name=Asserting), 78grand67_s=PostingsFormat(name=NestedPulsing), 18grand16_s=PostingsFormat(name=NestedPulsing), 69grand44_s=PostingsFormat(name=Asserting), 34grand20_s=PostingsFormat(name=Asserting), 5grand0_s=PostingsFormat(name=Asserting), 71grand14_s=PostingsFormat(name=Asserting), 7grand2_s=PostingsFormat(name=Asserting), 79grand75_s=PostingsFormat(name=NestedPulsing), 75grand63_s=Lucene41(blocksize=128), 65grand7_s=PostingsFormat(name=SimpleText), 43child9_s=PostingsFormat(name=SimpleText), 37grand23_s=PostingsFormat(name=Asserting), 57grand54_s=PostingsFormat(name=Asserting), 77grand29_s=Lucene41(blocksize=128), 31grand3_s=PostingsFormat(name=Asserting), 20child5_s=Lucene41(blocksize=128), 59grand36_s=Lucene41(blocksize=128), 35child9_s=Lucene
   [junit4]   2> 41(blocksize=128), 34grand15_s=Lucene41(blocksize=128), 39child4_s=PostingsFormat(name=SimpleText), 28child7_s=PostingsFormat(name=Asserting), 84grand72_s=Lucene41(blocksize=128), 33child32_s=Lucene41(blocksize=128), 38child0_s=PostingsFormat(name=Asserting), 62grand1_s=PostingsFormat(name=Asserting), 70grand6_s=Lucene41(blocksize=128), 45grand21_s=PostingsFormat(name=NestedPulsing), 58grand54_s=PostingsFormat(name=SimpleText), 16grand11_s=Lucene41(blocksize=128), 37child27_s=PostingsFormat(name=Asserting), 29child24_s=Lucene41(blocksize=128), 80grand30_s=PostingsFormat(name=Asserting), 36grand14_s=PostingsFormat(name=SimpleText), 41child7_s=PostingsFormat(name=NestedPulsing), 41grand22_s=Lucene41(blocksize=128), 56grand22_s=Lucene41(blocksize=128), 18child14_s=PostingsFormat(name=SimpleText), 49grand30_s=PostingsFormat(name=NestedPulsing), 52grand7_s=PostingsFormat(name=SimpleText), 62grand55_s=PostingsFormat(name=SimpleText), 38grand13_s=PostingsFormat(name=Asserting), 65grand20_s=Lucene41(blocksize=128), 82grand57_s=PostingsFormat(name=SimpleText), 42child0_s=PostingsFormat(name=NestedPulsing), 38child23_s=PostingsFormat(name=NestedPulsing), 81grand24_s=PostingsFormat(name=Asserting), 14child5_s=PostingsFormat(name=NestedPulsing), 28grand20_s=PostingsFormat(name=NestedPulsing), 39grand18_s=PostingsFormat(name=Asserting), 81grand58_s=PostingsFormat(name=SimpleText), 26child20_s=PostingsFormat(name=NestedPulsing), 59grand41_s=PostingsFormat(name=Asserting), 40child24_s=PostingsFormat(name=SimpleText), 31child23_s=Lucene41(blocksize=128), 84grand79_s=PostingsFormat(name=NestedPulsing), 72grand55_s=PostingsFormat(name=Asserting), 22grand14_s=Lucene41(blocksize=128), 74grand14_s=PostingsFormat(name=SimpleText), 54grand1_s=PostingsFormat(name=SimpleText), 20grand12_s=Lucene41(blocksize=128), 15child5_s=PostingsFormat(name=Asserting), 77grand1_s=PostingsFormat(name=Asserting), 33grand14_s=Lucene41(blocksize=128), 33child0_s=PostingsFormat(name=SimpleText), 37child30_s=PostingsFormat(name=Asserting), 41child34_s=PostingsFormat(name=SimpleText), 40grand22_s=PostingsFormat(name=SimpleText), 31grand29_s=PostingsFormat(name=Asserting), 45grand5_s=PostingsFormat(name=SimpleText), 82grand77_s=PostingsFormat(name=NestedPulsing), 24child19_s=PostingsFormat(name=NestedPulsing), 58grand7_s=PostingsFormat(name=SimpleText), 55grand36_s=Lucene41(blocksize=128), 68grand35_s=PostingsFormat(name=SimpleText), 9child0_s=PostingsFormat(name=Asserting), 80grand23_s=PostingsFormat(name=Asserting), 52grand51_s=Lucene41(blocksize=128), 61grand44_s=PostingsFormat(name=Asserting), 77grand14_s=Lucene41(blocksize=128), 68grand62_s=PostingsFormat(name=NestedPulsing), 58grand24_s=Lucene41(blocksize=128), 58grand35_s=Lucene41(blocksize=128), 19child17_s=PostingsFormat(name=NestedPulsing), 70grand64_s=PostingsFormat(name=Asserting), 33child8_s=PostingsFormat(name=SimpleText), 83grand28_s=Lucene41(blocksize=128), 73grand47_s=Lucene41(blocksize=128), 36child27_s=PostingsFormat(name=SimpleText), 49grand39_s=PostingsFormat(name=Asserting), 28grand14_s=PostingsFormat(name=Asserting), 57grand33_s=PostingsFormat(name=SimpleText), 12child7_s=PostingsFormat(name=NestedPulsing), 51grand50_s=Lucene41(blocksize=128), 32child3_s=PostingsFormat(name=SimpleText), 35child34_s=Lucene41(blocksize=128), 31grand19_s=PostingsFormat(name=SimpleText), 40grand16_s=PostingsFormat(name=Asserting), 51grand0_s=PostingsFormat(name=SimpleText), 18child7_s=PostingsFormat(name=NestedPulsing), 76grand14_s=PostingsFormat(name=NestedPulsing), 28child20_s=PostingsFormat(name=NestedPulsing), 14child12_s=PostingsFormat(name=SimpleText), 42child8_s=PostingsFormat(name=NestedPulsing), 65grand50_s=PostingsFormat(name=SimpleText)}, docValues:{}, sim=DefaultSimilarity, locale=fi_FI, timezone=Europe/Stockholm
   [junit4]   2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=16,threads=1,free=255645672,total=536870912
   [junit4]   2> NOTE: All tests run in this JVM: [TestSweetSpotSimilarityFactory, TestManagedSchemaFieldResource, StandardRequestHandlerTest, BadComponentTest, BlockDirectoryTest, TestReversedWildcardFilterFactory, TestPHPSerializedResponseWriter, TestCollationField, BasicDistributedZk2Test, TestFieldResource, SuggesterWFSTTest, BasicFunctionalityTest, SpellingQueryConverterTest, ChaosMonkeySafeLeaderTest, TestReload, XsltUpdateRequestHandlerTest, TestRangeQuery, TestCharFilters, TestComponentsName, ReturnFieldsTest, InfoHandlerTest, DistributedQueryElevationComponentTest, CurrencyFieldXmlFileTest, TestMultiCoreConfBootstrap, FileUtilsTest, QueryResultKeyTest, SpellCheckCollatorTest, ShardSplitTest, TestPostingsSolrHighlighter, TestFiltering, OverseerTest, DistributedSpellCheckComponentTest, FieldMutatingUpdateProcessorTest, DisMaxRequestHandlerTest, TestCSVResponseWriter, CachingDirectoryFactoryTest, ChaosMonkeyNothingIsSafeTest, TestDocumentBuilder, TestTrie, HdfsUnloadDistributedZkTest, ParsingFieldUpdateProcessorsTest, DirectUpdateHandlerTest, SolrIndexSplitterTest, AliasIntegrationTest, TestSuggestSpellingConverter, TestJmxMonitoredMap, TestSolrJ, TestBinaryField, TestQuerySenderNoQuery, TestCodecSupport, CoreAdminCreateDiscoverTest, TestLuceneMatchVersion, DirectSolrSpellCheckerTest, OpenCloseCoreStressTest, XmlUpdateRequestHandlerTest, TestCSVLoader, TestSolrXmlPersistence, TestSchemaVersionResource, TestRecovery, TestSolrXMLSerializer, FullSolrCloudDistribCmdsTest]
   [junit4] Completed on J1 in 1688.04s, 1 test, 1 error <<< FAILURES!

[...truncated 517 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:395: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:375: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:450: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1233: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:876: There were test failures: 321 suites, 1364 tests, 1 error, 35 ignored (6 assumptions)

Total time: 72 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure