lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_25) - Build # 6318 - Failure!
Date Wed, 26 Jun 2013 13:01:52 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6318/
Java: 32bit/jdk1.7.0_25 -client -XX:+UseConcMarkSweepGC

2 tests failed.
FAILED:  junit.framework.TestSuite.org.apache.solr.cloud.ChaosMonkeySafeLeaderTest

Error Message:
Suite timeout exceeded (>= 7200000 msec).

Stack Trace:
java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
	at __randomizedtesting.SeedInfo.seed([75147286676B0327]:0)


REGRESSION:  org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch

Error Message:
Test abandoned because suite timeout was reached.

Stack Trace:
java.lang.Exception: Test abandoned because suite timeout was reached.
	at __randomizedtesting.SeedInfo.seed([75147286676B0327]:0)




Build Log:
[...truncated 10128 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4]   2> 256900 T691 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 256908 T691 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeySafeLeaderTest-1372244447187
[junit4:junit4]   2> 256908 T691 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 256909 T692 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 257009 T691 oasc.ZkTestServer.run start zk server on port:57582
[junit4:junit4]   2> 257011 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 257087 T698 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@161b7c7 name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 257087 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 257088 T691 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 257093 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 257094 T700 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e1095 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 257094 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 257095 T691 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 257098 T691 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 257099 T691 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 257101 T691 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 257102 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 257103 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 257107 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 257108 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 257113 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 257113 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 257116 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 257117 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 257120 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 257120 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 257123 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 257124 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 257127 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 257128 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 257132 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 257133 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 257136 T691 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 257137 T691 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 257243 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 257246 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48463
[junit4:junit4]   2> 257247 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 257247 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 257248 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422
[junit4:junit4]   2> 257248 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/solr.xml
[junit4:junit4]   2> 257248 T691 oasc.CoreContainer.<init> New CoreContainer 11425805
[junit4:junit4]   2> 257249 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/'
[junit4:junit4]   2> 257249 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/'
[junit4:junit4]   2> 257366 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 257366 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 257366 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 257367 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 257367 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 257367 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 257368 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 257368 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 257368 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 257368 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 257380 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 257381 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 257381 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 257382 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 257383 T711 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@89f5e5 name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 257384 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 257385 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 257389 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 257391 T713 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@42a377 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 257391 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 257393 T691 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 257397 T691 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 257400 T691 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 257402 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48463_
[junit4:junit4]   2> 257404 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48463_
[junit4:junit4]   2> 257408 T691 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 257414 T691 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 257418 T691 oasc.Overseer.start Overseer (id=89931412091043843-127.0.0.1:48463_-n_0000000000) starting
[junit4:junit4]   2> 257423 T691 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 257428 T715 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 257429 T691 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 257432 T691 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 257435 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 257439 T714 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 257458 T716 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 257458 T716 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 258944 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 258945 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48463_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48463"}
[junit4:junit4]   2> 258946 T714 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 258946 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 258952 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 259460 T716 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/collection1
[junit4:junit4]   2> 259461 T716 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 259462 T716 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 259462 T716 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 259464 T716 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/collection1/'
[junit4:junit4]   2> 259465 T716 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/collection1/lib/README' to classloader
[junit4:junit4]   2> 259466 T716 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 259565 T716 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 259667 T716 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 259670 T716 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 259685 T716 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 260560 T716 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 260566 T716 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 260577 T716 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 260596 T716 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 260602 T716 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 260607 T716 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 260609 T716 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 260609 T716 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 260610 T716 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 260611 T716 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 260611 T716 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 260612 T716 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 260612 T716 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372244447422/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/control/data/
[junit4:junit4]   2> 260613 T716 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 260613 T716 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 260614 T716 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/control/data
[junit4:junit4]   2> 260615 T716 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/control/data/index/
[junit4:junit4]   2> 260615 T716 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 260616 T716 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/control/data/index
[junit4:junit4]   2> 260620 T716 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 260620 T716 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 260624 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 260625 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 260640 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 260641 T716 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 260642 T716 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 260642 T716 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 260643 T716 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 260644 T716 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 260644 T716 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 260649 T716 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 260655 T716 oass.SolrIndexSearcher.<init> Opening Searcher@1b5238f main
[junit4:junit4]   2> 260656 T716 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 260657 T716 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 260664 T717 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b5238f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 260666 T716 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 260667 T716 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48463 collection:control_collection shard:shard1
[junit4:junit4]   2> 260668 T716 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 260679 T716 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 260683 T716 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 260683 T716 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 260683 T716 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48463/collection1/
[junit4:junit4]   2> 260684 T716 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 260684 T716 oasc.SyncStrategy.syncToMe http://127.0.0.1:48463/collection1/ has no replicas
[junit4:junit4]   2> 260685 T716 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48463/collection1/
[junit4:junit4]   2> 260685 T716 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 261967 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 261981 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 262009 T716 oasc.ZkController.register We are http://127.0.0.1:48463/collection1/ and leader is http://127.0.0.1:48463/collection1/
[junit4:junit4]   2> 262010 T716 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48463
[junit4:junit4]   2> 262010 T716 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 262010 T716 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 262011 T716 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 262013 T716 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 262015 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 262015 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 262016 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 262022 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 262023 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 262024 T720 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1642a name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 262025 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 262026 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 262029 T691 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 262121 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 262123 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42520
[junit4:junit4]   2> 262124 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 262124 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 262124 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309
[junit4:junit4]   2> 262125 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/solr.xml
[junit4:junit4]   2> 262125 T691 oasc.CoreContainer.<init> New CoreContainer 15795888
[junit4:junit4]   2> 262125 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/'
[junit4:junit4]   2> 262126 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/'
[junit4:junit4]   2> 262223 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 262223 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 262224 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 262224 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 262224 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 262225 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 262225 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 262226 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 262226 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 262227 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 262231 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 262231 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 262232 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 262233 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 262234 T731 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1035763 name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 262235 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 262237 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 262241 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 262242 T733 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5d1033 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 262242 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 262247 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 263250 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42520_
[junit4:junit4]   2> 263252 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42520_
[junit4:junit4]   2> 263257 T713 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 263257 T733 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 263257 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 263257 T720 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 263280 T734 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 263281 T734 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 263489 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 263490 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48463_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48463"}
[junit4:junit4]   2> 263495 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42520_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42520"}
[junit4:junit4]   2> 263496 T714 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4]   2> 263496 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 263503 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 263503 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 263503 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 264283 T734 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/collection1
[junit4:junit4]   2> 264283 T734 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 264285 T734 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 264285 T734 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 264287 T734 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/collection1/'
[junit4:junit4]   2> 264288 T734 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/collection1/lib/README' to classloader
[junit4:junit4]   2> 264289 T734 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 264396 T734 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 264499 T734 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 264501 T734 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 264508 T734 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 265424 T734 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 265434 T734 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 265448 T734 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 265462 T734 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 265468 T734 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 265475 T734 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 265485 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 265485 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 265486 T734 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 265486 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 265487 T734 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 265487 T734 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 265487 T734 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372244452309/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/
[junit4:junit4]   2> 265487 T734 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 265488 T734 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 265488 T734 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1
[junit4:junit4]   2> 265488 T734 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index/
[junit4:junit4]   2> 265489 T734 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 265489 T734 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index
[junit4:junit4]   2> 265494 T734 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 265494 T734 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 265496 T734 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 265496 T734 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 265496 T734 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 265497 T734 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 265498 T734 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 265498 T734 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 265498 T734 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 265499 T734 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 265499 T734 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 265501 T734 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 265505 T734 oass.SolrIndexSearcher.<init> Opening Searcher@a2bc2a main
[junit4:junit4]   2> 265506 T734 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 265506 T734 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 265526 T735 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a2bc2a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 265530 T734 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 265530 T734 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42520 collection:collection1 shard:shard1
[junit4:junit4]   2> 265531 T734 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 265540 T734 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 265544 T734 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 265544 T734 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 265544 T734 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42520/collection1/
[junit4:junit4]   2> 265545 T734 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 265545 T734 oasc.SyncStrategy.syncToMe http://127.0.0.1:42520/collection1/ has no replicas
[junit4:junit4]   2> 265545 T734 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42520/collection1/
[junit4:junit4]   2> 265546 T734 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 266521 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 266530 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 266530 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 266530 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 266555 T734 oasc.ZkController.register We are http://127.0.0.1:42520/collection1/ and leader is http://127.0.0.1:42520/collection1/
[junit4:junit4]   2> 266556 T734 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42520
[junit4:junit4]   2> 266556 T734 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 266557 T734 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 266557 T734 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 266807 T734 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 266809 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 266810 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 266811 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 266917 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 266919 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42023
[junit4:junit4]   2> 266920 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 266920 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 266928 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106
[junit4:junit4]   2> 266928 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/solr.xml
[junit4:junit4]   2> 266928 T691 oasc.CoreContainer.<init> New CoreContainer 23862425
[junit4:junit4]   2> 266929 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/'
[junit4:junit4]   2> 266929 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/'
[junit4:junit4]   2> 267039 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 267040 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 267040 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 267040 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 267041 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 267041 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 267041 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 267041 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 267042 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 267052 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 267055 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 267055 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 267056 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 267057 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 267059 T747 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dc2f0d name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 267059 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 267061 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 267064 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 267065 T749 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fe4b58 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 267065 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 267068 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 268037 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 268038 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42520_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42520"}
[junit4:junit4]   2> 268040 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 268041 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 268040 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 268040 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 268070 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42023_
[junit4:junit4]   2> 268071 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42023_
[junit4:junit4]   2> 268073 T720 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 268073 T733 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 268073 T713 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 268073 T749 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 268073 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 268074 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 268074 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 268073 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 268085 T750 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 268086 T750 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 269545 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 269546 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42023_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42023"}
[junit4:junit4]   2> 269546 T714 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 269546 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 269550 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 269550 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 269550 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 269550 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 270087 T750 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/collection1
[junit4:junit4]   2> 270087 T750 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 270088 T750 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 270088 T750 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 270089 T750 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/collection1/'
[junit4:junit4]   2> 270089 T750 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/collection1/lib/README' to classloader
[junit4:junit4]   2> 270090 T750 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 270142 T750 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 270229 T750 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 270230 T750 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 270242 T750 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 271096 T750 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 271103 T750 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 271113 T750 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 271127 T750 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 271130 T750 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 271132 T750 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 271133 T750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 271134 T750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 271134 T750 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 271135 T750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 271135 T750 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 271135 T750 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 271136 T750 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372244457106/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/
[junit4:junit4]   2> 271136 T750 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 271136 T750 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 271136 T750 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2
[junit4:junit4]   2> 271137 T750 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index/
[junit4:junit4]   2> 271137 T750 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 271137 T750 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index
[junit4:junit4]   2> 271140 T750 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 271140 T750 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 271149 T750 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 271149 T750 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 271149 T750 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 271150 T750 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 271151 T750 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 271151 T750 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 271151 T750 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 271152 T750 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 271152 T750 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 271155 T750 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 271157 T750 oass.SolrIndexSearcher.<init> Opening Searcher@18da82a main
[junit4:junit4]   2> 271162 T750 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 271162 T750 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 271177 T751 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18da82a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 271181 T750 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 271181 T750 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42023 collection:collection1 shard:shard2
[junit4:junit4]   2> 271182 T750 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 271186 T750 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 271188 T750 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 271188 T750 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 271188 T750 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42023/collection1/
[junit4:junit4]   2> 271188 T750 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 271189 T750 oasc.SyncStrategy.syncToMe http://127.0.0.1:42023/collection1/ has no replicas
[junit4:junit4]   2> 271189 T750 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42023/collection1/
[junit4:junit4]   2> 271189 T750 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 272561 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 272566 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 272566 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 272566 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 272566 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 272595 T750 oasc.ZkController.register We are http://127.0.0.1:42023/collection1/ and leader is http://127.0.0.1:42023/collection1/
[junit4:junit4]   2> 272596 T750 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42023
[junit4:junit4]   2> 272596 T750 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 272596 T750 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 272597 T750 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 272598 T750 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 272599 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 272600 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 272600 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 272682 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 272684 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60386
[junit4:junit4]   2> 272685 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 272685 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 272685 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883
[junit4:junit4]   2> 272685 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/solr.xml
[junit4:junit4]   2> 272686 T691 oasc.CoreContainer.<init> New CoreContainer 13830250
[junit4:junit4]   2> 272686 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/'
[junit4:junit4]   2> 272687 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/'
[junit4:junit4]   2> 272782 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 272782 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 272783 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 272783 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 272783 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 272784 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 272784 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 272785 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 272785 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 272785 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 272788 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 272789 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 272789 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 272790 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 272799 T763 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@35028a name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 272799 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 272801 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 272804 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 272805 T765 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51e649 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 272805 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 272808 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 273810 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60386_
[junit4:junit4]   2> 273811 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60386_
[junit4:junit4]   2> 273815 T749 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 273815 T733 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 273815 T720 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 273815 T713 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 273815 T765 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 273815 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 273816 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 273815 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 273815 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 273821 T766 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 273821 T766 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 274071 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 274072 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42023_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42023"}
[junit4:junit4]   2> 274074 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60386_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60386"}
[junit4:junit4]   2> 274075 T714 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 274075 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4]   2> 274079 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 274079 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 274079 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 274079 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 274079 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 274823 T766 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/collection1
[junit4:junit4]   2> 274823 T766 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 274824 T766 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 274824 T766 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 274825 T766 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/collection1/'
[junit4:junit4]   2> 274825 T766 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/collection1/lib/README' to classloader
[junit4:junit4]   2> 274826 T766 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 274877 T766 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 274953 T766 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 274955 T766 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 274959 T766 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 275775 T766 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 275784 T766 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 275788 T766 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 275809 T766 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 275813 T766 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 275816 T766 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 275817 T766 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 275817 T766 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 275818 T766 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 275819 T766 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 275819 T766 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 275819 T766 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 275820 T766 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372244462883/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3/
[junit4:junit4]   2> 275820 T766 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 275820 T766 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 275821 T766 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3
[junit4:junit4]   2> 275821 T766 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3/index/
[junit4:junit4]   2> 275822 T766 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 275822 T766 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3/index
[junit4:junit4]   2> 275825 T766 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 275825 T766 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 275827 T766 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 275827 T766 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 275827 T766 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 275828 T766 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 275829 T766 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 275829 T766 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 275829 T766 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 275836 T766 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 275837 T766 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 275839 T766 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 275842 T766 oass.SolrIndexSearcher.<init> Opening Searcher@8408e5 main
[junit4:junit4]   2> 275842 T766 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 275843 T766 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 275848 T767 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8408e5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 275858 T766 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 275858 T766 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60386 collection:collection1 shard:shard3
[junit4:junit4]   2> 275859 T766 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4]   2> 275863 T766 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 275865 T766 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 275865 T766 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 275865 T766 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60386/collection1/
[junit4:junit4]   2> 275866 T766 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 275866 T766 oasc.SyncStrategy.syncToMe http://127.0.0.1:60386/collection1/ has no replicas
[junit4:junit4]   2> 275866 T766 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60386/collection1/
[junit4:junit4]   2> 275866 T766 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4]   2> 277098 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 277106 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 277106 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 277106 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 277106 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 277106 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 277123 T766 oasc.ZkController.register We are http://127.0.0.1:60386/collection1/ and leader is http://127.0.0.1:60386/collection1/
[junit4:junit4]   2> 277124 T766 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60386
[junit4:junit4]   2> 277124 T766 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 277124 T766 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 277124 T766 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 277126 T766 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 277127 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 277127 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 277128 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 277213 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 277215 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59918
[junit4:junit4]   2> 277216 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 277216 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 277216 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410
[junit4:junit4]   2> 277217 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/solr.xml
[junit4:junit4]   2> 277217 T691 oasc.CoreContainer.<init> New CoreContainer 17723565
[junit4:junit4]   2> 277217 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/'
[junit4:junit4]   2> 277218 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/'
[junit4:junit4]   2> 277333 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 277334 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 277334 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 277334 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 277335 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 277335 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 277335 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 277335 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 277336 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 277336 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 277339 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 277339 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 277340 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 277341 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 277342 T779 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1416932 name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 277342 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 277344 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 277347 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 277348 T781 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ddee5e name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 277348 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 277359 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 278362 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59918_
[junit4:junit4]   2> 278363 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59918_
[junit4:junit4]   2> 278365 T749 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 278365 T733 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 278366 T720 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 278366 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278365 T765 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 278365 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278365 T781 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 278365 T713 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 278366 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278366 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278367 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278370 T782 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 278370 T782 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 278612 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 278613 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard3",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60386_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60386"}
[junit4:junit4]   2> 278617 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59918_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59918"}
[junit4:junit4]   2> 278617 T714 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 278618 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 278623 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278623 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278623 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278623 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278623 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 278623 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 279371 T782 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/collection1
[junit4:junit4]   2> 279372 T782 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 279373 T782 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 279373 T782 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 279374 T782 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/collection1/'
[junit4:junit4]   2> 279375 T782 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/collection1/lib/README' to classloader
[junit4:junit4]   2> 279375 T782 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 279448 T782 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 279530 T782 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 279531 T782 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 279535 T782 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 280351 T782 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 280367 T782 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 280371 T782 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 280391 T782 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 280394 T782 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 280396 T782 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 280397 T782 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 280398 T782 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 280398 T782 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 280399 T782 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 280399 T782 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 280399 T782 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 280400 T782 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372244467410/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/
[junit4:junit4]   2> 280400 T782 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 280400 T782 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 280401 T782 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4
[junit4:junit4]   2> 280401 T782 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index/
[junit4:junit4]   2> 280401 T782 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 280401 T782 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index
[junit4:junit4]   2> 280404 T782 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 280404 T782 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 280406 T782 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 280406 T782 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 280407 T782 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 280408 T782 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 280408 T782 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 280408 T782 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 280409 T782 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 280409 T782 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 280410 T782 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 280412 T782 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 280424 T782 oass.SolrIndexSearcher.<init> Opening Searcher@14aedaa main
[junit4:junit4]   2> 280425 T782 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 280425 T782 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 280431 T783 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14aedaa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 280433 T782 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 280434 T782 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59918 collection:collection1 shard:shard1
[junit4:junit4]   2> 280457 T782 oasc.ZkController.register We are http://127.0.0.1:59918/collection1/ and leader is http://127.0.0.1:42520/collection1/
[junit4:junit4]   2> 280457 T782 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59918
[junit4:junit4]   2> 280457 T782 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 280458 T782 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C1773 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1773_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 280461 T784 C1773 P59918 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 280462 T782 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 280462 T784 C1773 P59918 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 280463 T784 C1773 P59918 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 280463 T784 C1773 P59918 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 280463 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 280463 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 280464 T784 C1773 P59918 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 280464 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 280472 T729 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 280556 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 280558 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33323
[junit4:junit4]   2> 280558 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 280558 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 280559 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746
[junit4:junit4]   2> 280559 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/solr.xml
[junit4:junit4]   2> 280559 T691 oasc.CoreContainer.<init> New CoreContainer 20503918
[junit4:junit4]   2> 280560 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/'
[junit4:junit4]   2> 280560 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/'
[junit4:junit4]   2> 280666 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 280667 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 280667 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 280668 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 280668 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 280668 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 280669 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 280669 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 280670 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 280670 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 280673 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 280673 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 280674 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 280675 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 280676 T796 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fa155 name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 280676 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 280678 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 280681 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 280682 T798 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@467d90 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 280683 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 280685 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 281629 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 281629 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59918_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59918"}
[junit4:junit4]   2> 281632 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281632 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281633 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281633 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281632 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281632 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281632 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281687 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33323_
[junit4:junit4]   2> 281689 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33323_
[junit4:junit4]   2> 281691 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 281691 T713 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281691 T720 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281691 T798 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281691 T733 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281691 T765 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281692 T781 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281691 T749 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 281692 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 281692 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 281692 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 281691 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 281691 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 281693 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 281696 T799 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 281697 T799 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 282473 T729 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 282473 T729 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:59918_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002 
[junit4:junit4]   2> 283145 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 283146 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"6",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:33323_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:33323"}
[junit4:junit4]   2> 283146 T714 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 283146 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 283149 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283149 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283149 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283149 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283149 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283149 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283149 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 283699 T799 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/collection1
[junit4:junit4]   2> 283699 T799 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 283700 T799 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 283700 T799 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 283701 T799 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/collection1/'
[junit4:junit4]   2> 283702 T799 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/collection1/lib/README' to classloader
[junit4:junit4]   2> 283703 T799 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 283766 T799 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 283894 T799 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 283895 T799 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 283902 T799 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C1774 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1774_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284474 T784 C1774 P59918 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42520/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 284479 T784 C1774 P59918 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1775 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1775_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284491 T784 C1775 P59918 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59918 START replicas=[http://127.0.0.1:42520/collection1/] nUpdates=100
[junit4:junit4]   2> 284492 T784 C1775 P59918 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 284493 T784 C1775 P59918 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 284493 T784 C1775 P59918 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 284493 T784 C1775 P59918 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 284494 T784 C1775 P59918 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 284494 T784 C1775 P59918 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42520/collection1/. core=collection1
[junit4:junit4]   2> 284494 T784 C1775 P59918 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1776 name=collection1 org.apache.solr.core.SolrCore@3be7b2 url=http://127.0.0.1:42520/collection1 node=127.0.0.1:42520_ C1776_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42520_, base_url=http://127.0.0.1:42520, leader=true}
[junit4:junit4]   2> 284514 T727 C1776 P42520 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> ASYNC  NEW_CORE C1777 name=collection1 org.apache.solr.core.SolrCore@3be7b2 url=http://127.0.0.1:42520/collection1 node=127.0.0.1:42520_ C1777_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42520_, base_url=http://127.0.0.1:42520, leader=true}
[junit4:junit4]   2> 284530 T728 C1777 P42520 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 284533 T728 C1777 P42520 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 284533 T728 C1777 P42520 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> ASYNC  NEW_CORE C1778 name=collection1 org.apache.solr.core.SolrCore@3be7b2 url=http://127.0.0.1:42520/collection1 node=127.0.0.1:42520_ C1778_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42520_, base_url=http://127.0.0.1:42520, leader=true}
[junit4:junit4]   2> 284546 T728 C1778 P42520 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4]   2> 284546 T728 C1778 P42520 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 284547 T728 C1778 P42520 oass.SolrIndexSearcher.<init> Opening Searcher@18fba97 realtime
[junit4:junit4]   2> 284547 T728 C1778 P42520 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 284548 T728 C1778 P42520 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 32
[junit4:junit4]   2> ASYNC  NEW_CORE C1779 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1779_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284586 T784 C1779 P59918 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 284587 T784 C1779 P59918 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4]   2> ASYNC  NEW_CORE C1780 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1780_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284598 T784 C1780 P59918 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> ASYNC  NEW_CORE C1781 name=collection1 org.apache.solr.core.SolrCore@3be7b2 url=http://127.0.0.1:42520/collection1 node=127.0.0.1:42520_ C1781_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42520_, base_url=http://127.0.0.1:42520, leader=true}
[junit4:junit4]   2> 284601 T726 C1781 P42520 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 284602 T726 C1781 P42520 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 284602 T784 C1780 P59918 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 284603 T784 C1780 P59918 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 284603 T784 C1780 P59918 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 284605 T727 C1781 P42520 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> ASYNC  NEW_CORE C1782 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1782_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284617 T784 C1782 P59918 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 284618 T784 C1782 P59918 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index.20130626080114897
[junit4:junit4]   2> 284619 T784 C1782 P59918 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index.20130626080114897 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1399418 fullCopy=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1783 name=collection1 org.apache.solr.core.SolrCore@3be7b2 url=http://127.0.0.1:42520/collection1 node=127.0.0.1:42520_ C1783_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42520_, base_url=http://127.0.0.1:42520, leader=true}
[junit4:junit4]   2> 284632 T728 C1783 P42520 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1 
[junit4:junit4]   2> ASYNC  NEW_CORE C1784 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1784_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284636 T784 C1784 P59918 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> ASYNC  NEW_CORE C1785 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1785_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284653 T784 C1785 P59918 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 284653 T784 C1785 P59918 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 284656 T784 C1785 P59918 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index,segFN=segments_2,generation=2}
[junit4:junit4]   2> 284657 T784 C1785 P59918 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 284657 T784 C1785 P59918 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 284658 T784 C1785 P59918 oass.SolrIndexSearcher.<init> Opening Searcher@6bfa26 main
[junit4:junit4]   2> 284666 T783 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6bfa26 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> ASYNC  NEW_CORE C1786 name=collection1 org.apache.solr.core.SolrCore@1530da8 url=http://127.0.0.1:59918/collection1 node=127.0.0.1:59918_ C1786_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59918_, base_url=http://127.0.0.1:59918}
[junit4:junit4]   2> 284667 T784 C1786 P59918 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index.20130626080114897 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index.20130626080114897;done=true>>]
[junit4:junit4]   2> 284668 T784 C1786 P59918 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index.20130626080114897
[junit4:junit4]   2> 284668 T784 C1786 P59918 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty4/index.20130626080114897
[junit4:junit4]   2> 284668 T784 C1786 P59918 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 284669 T784 C1786 P59918 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 284669 T784 C1786 P59918 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 284669 T784 C1786 P59918 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 284671 T784 C1786 P59918 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 284849 T799 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 284855 T799 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 284858 T799 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 284881 T799 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 284886 T799 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 284891 T799 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 284891 T799 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 284892 T799 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 284892 T799 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 284893 T799 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 284893 T799 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 284893 T799 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 284893 T799 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372244470746/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/
[junit4:junit4]   2> 284894 T799 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 284894 T799 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 284895 T799 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5
[junit4:junit4]   2> 284895 T799 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index/
[junit4:junit4]   2> 284895 T799 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 284896 T799 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index
[junit4:junit4]   2> 284917 T799 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 284918 T799 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 284920 T799 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 284920 T799 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 284921 T799 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 284931 T799 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 284932 T799 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 284932 T799 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 284935 T799 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 284935 T799 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 284936 T799 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 284938 T799 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 284941 T799 oass.SolrIndexSearcher.<init> Opening Searcher@290848 main
[junit4:junit4]   2> 284942 T799 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 284942 T799 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 284954 T802 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@290848 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 284956 T799 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 284957 T799 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33323 collection:collection1 shard:shard2
[junit4:junit4]   2> 284962 T799 oasc.ZkController.register We are http://127.0.0.1:33323/collection1/ and leader is http://127.0.0.1:42023/collection1/
[junit4:junit4]   2> 284962 T799 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33323
[junit4:junit4]   2> 284962 T799 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 284962 T799 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C1787 name=collection1 org.apache.solr.core.SolrCore@1c51e8 url=http://127.0.0.1:33323/collection1 node=127.0.0.1:33323_ C1787_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:33323_, base_url=http://127.0.0.1:33323}
[junit4:junit4]   2> 284963 T803 C1787 P33323 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 284963 T799 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 284963 T803 C1787 P33323 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 284964 T803 C1787 P33323 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 284964 T803 C1787 P33323 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 284964 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 284965 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 284965 T803 C1787 P33323 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 284965 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 284971 T744 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 285079 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 285081 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44127
[junit4:junit4]   2> 285082 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 285083 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 285083 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249
[junit4:junit4]   2> 285084 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/solr.xml
[junit4:junit4]   2> 285084 T691 oasc.CoreContainer.<init> New CoreContainer 699810
[junit4:junit4]   2> 285085 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/'
[junit4:junit4]   2> 285085 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/'
[junit4:junit4]   2> 285231 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 285232 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 285232 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 285233 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 285233 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 285234 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 285234 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 285234 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 285235 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 285235 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 285240 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 285241 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 285241 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 285243 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 285244 T815 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e5e6af name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 285245 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 285252 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 285263 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 285264 T817 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@145bf5d name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 285264 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 285267 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 286154 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 286155 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59918_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59918"}
[junit4:junit4]   2> 286157 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"6",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:33323_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:33323"}
[junit4:junit4]   2> 286159 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286159 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286160 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286159 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286159 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286159 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286160 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286160 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286270 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44127_
[junit4:junit4]   2> 286272 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44127_
[junit4:junit4]   2> 286274 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 6)
[junit4:junit4]   2> 286274 T720 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286274 T798 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286274 T765 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286275 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286274 T713 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286274 T749 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286274 T733 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286274 T817 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286274 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286276 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286276 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286275 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286275 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286274 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 286277 T781 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 286286 T818 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 286286 T818 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 286972 T744 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 286972 T744 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:33323_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001 
[junit4:junit4]   2> 287665 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 287666 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"7",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:44127_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:44127"}
[junit4:junit4]   2> 287666 T714 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 287666 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4]   2> 287668 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 287669 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 288288 T818 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/collection1
[junit4:junit4]   2> 288288 T818 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 288289 T818 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 288289 T818 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 288290 T818 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/collection1/'
[junit4:junit4]   2> 288291 T818 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/collection1/lib/README' to classloader
[junit4:junit4]   2> 288291 T818 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 288359 T818 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 288465 T818 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 288466 T818 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 288474 T818 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C1788 name=collection1 org.apache.solr.core.SolrCore@1c51e8 url=http://127.0.0.1:33323/collection1 node=127.0.0.1:33323_ C1788_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:33323_, base_url=http://127.0.0.1:33323}
[junit4:junit4]   2> 288973 T803 C1788 P33323 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42023/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 288974 T803 C1788 P33323 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:33323 START replicas=[http://127.0.0.1:42023/collection1/] nUpdates=100
[junit4:junit4]   2> 288975 T803 C1788 P33323 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 288975 T803 C1788 P33323 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 288975 T803 C1788 P33323 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 288975 T803 C1788 P33323 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 288976 T803 C1788 P33323 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 288976 T803 C1788 P33323 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42023/collection1/. core=collection1
[junit4:junit4]   2> 288976 T803 C1788 P33323 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1789 name=collection1 org.apache.solr.core.SolrCore@938e2d url=http://127.0.0.1:42023/collection1 node=127.0.0.1:42023_ C1789_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42023_, base_url=http://127.0.0.1:42023, leader=true}
[junit4:junit4]   2> 288989 T744 C1789 P42023 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> ASYNC  NEW_CORE C1790 name=collection1 org.apache.solr.core.SolrCore@938e2d url=http://127.0.0.1:42023/collection1 node=127.0.0.1:42023_ C1790_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42023_, base_url=http://127.0.0.1:42023, leader=true}
[junit4:junit4]   2> 289001 T745 C1790 P42023 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 289003 T745 C1790 P42023 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 289004 T745 C1790 P42023 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> ASYNC  NEW_CORE C1791 name=collection1 org.apache.solr.core.SolrCore@938e2d url=http://127.0.0.1:42023/collection1 node=127.0.0.1:42023_ C1791_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42023_, base_url=http://127.0.0.1:42023, leader=true}
[junit4:junit4]   2> 289023 T745 C1791 P42023 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4]   2> 289024 T745 C1791 P42023 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 289025 T745 C1791 P42023 oass.SolrIndexSearcher.<init> Opening Searcher@18de0cb realtime
[junit4:junit4]   2> 289025 T745 C1791 P42023 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 289025 T745 C1791 P42023 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 32
[junit4:junit4]   2> ASYNC  NEW_CORE C1792 name=collection1 org.apache.solr.core.SolrCore@1c51e8 url=http://127.0.0.1:33323/collection1 node=127.0.0.1:33323_ C1792_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:33323_, base_url=http://127.0.0.1:33323}
[junit4:junit4]   2> 289026 T803 C1792 P33323 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 289026 T803 C1792 P33323 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 289028 T743 C1791 P42023 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 289028 T743 C1791 P42023 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 289029 T803 C1792 P33323 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 289029 T803 C1792 P33323 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 289029 T803 C1792 P33323 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 289031 T744 C1791 P42023 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 289032 T803 C1792 P33323 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 289034 T803 C1792 P33323 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index.20130626080119311
[junit4:junit4]   2> 289034 T803 C1792 P33323 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index.20130626080119311 lockFactory=org.apache.lucene.store.NativeFSLockFactory@107e657 fullCopy=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1793 name=collection1 org.apache.solr.core.SolrCore@938e2d url=http://127.0.0.1:42023/collection1 node=127.0.0.1:42023_ C1793_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42023_, base_url=http://127.0.0.1:42023, leader=true}
[junit4:junit4]   2> 289043 T745 C1793 P42023 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> ASYNC  NEW_CORE C1794 name=collection1 org.apache.solr.core.SolrCore@1c51e8 url=http://127.0.0.1:33323/collection1 node=127.0.0.1:33323_ C1794_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:33323_, base_url=http://127.0.0.1:33323}
[junit4:junit4]   2> 289045 T803 C1794 P33323 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> ASYNC  NEW_CORE C1795 name=collection1 org.apache.solr.core.SolrCore@1c51e8 url=http://127.0.0.1:33323/collection1 node=127.0.0.1:33323_ C1795_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:33323_, base_url=http://127.0.0.1:33323}
[junit4:junit4]   2> 289058 T803 C1795 P33323 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 289059 T803 C1795 P33323 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 289061 T803 C1795 P33323 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index,segFN=segments_2,generation=2}
[junit4:junit4]   2> 289062 T803 C1795 P33323 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 289063 T803 C1795 P33323 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 289063 T803 C1795 P33323 oass.SolrIndexSearcher.<init> Opening Searcher@1a27575 main
[junit4:junit4]   2> 289065 T802 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a27575 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 289065 T803 C1795 P33323 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index.20130626080119311 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index.20130626080119311;done=true>>]
[junit4:junit4]   2> 289066 T803 C1795 P33323 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index.20130626080119311
[junit4:junit4]   2> 289066 T803 C1795 P33323 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty5/index.20130626080119311
[junit4:junit4]   2> 289067 T803 C1795 P33323 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 289067 T803 C1795 P33323 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 289067 T803 C1795 P33323 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 289067 T803 C1795 P33323 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 289069 T803 C1795 P33323 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 289176 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 289177 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"6",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:33323_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:33323"}
[junit4:junit4]   2> 289204 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289204 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289204 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289204 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289204 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289204 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289205 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289204 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 289443 T818 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 289449 T818 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 289452 T818 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 289473 T818 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 289477 T818 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 289480 T818 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 289481 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 289481 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 289482 T818 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 289482 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 289483 T818 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 289483 T818 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 289483 T818 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372244475249/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty6/
[junit4:junit4]   2> 289483 T818 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1512c2e
[junit4:junit4]   2> 289484 T818 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 289484 T818 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty6
[junit4:junit4]   2> 289484 T818 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty6/index/
[junit4:junit4]   2> 289485 T818 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 289485 T818 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty6/index
[junit4:junit4]   2> 289488 T818 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 289488 T818 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 289490 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 289490 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 289491 T818 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 289496 T818 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 289513 T818 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 289513 T818 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 289514 T818 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 289515 T818 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 289515 T818 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 289518 T818 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 289521 T818 oass.SolrIndexSearcher.<init> Opening Searcher@d9557f main
[junit4:junit4]   2> 289521 T818 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 289522 T818 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 289539 T821 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d9557f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 289541 T818 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 289541 T818 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44127 collection:collection1 shard:shard3
[junit4:junit4]   2> 289544 T818 oasc.ZkController.register We are http://127.0.0.1:44127/collection1/ and leader is http://127.0.0.1:60386/collection1/
[junit4:junit4]   2> 289544 T818 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44127
[junit4:junit4]   2> 289545 T818 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 289545 T818 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C1796 name=collection1 org.apache.solr.core.SolrCore@c5301b url=http://127.0.0.1:44127/collection1 node=127.0.0.1:44127_ C1796_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:44127_, base_url=http://127.0.0.1:44127}
[junit4:junit4]   2> 289545 T822 C1796 P44127 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 289546 T818 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 289546 T822 C1796 P44127 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 289547 T822 C1796 P44127 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 289547 T822 C1796 P44127 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 289547 T691 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 289548 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 289548 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 289550 T822 C1796 P44127 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 289554 T759 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 289641 T691 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 289644 T691 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47226
[junit4:junit4]   2> 289644 T691 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 289645 T691 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 289645 T691 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832
[junit4:junit4]   2> 289645 T691 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/solr.xml
[junit4:junit4]   2> 289646 T691 oasc.CoreContainer.<init> New CoreContainer 8280406
[junit4:junit4]   2> 289646 T691 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/'
[junit4:junit4]   2> 289646 T691 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/'
[junit4:junit4]   2> 289755 T691 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 289756 T691 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 289756 T691 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 289756 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 289756 T691 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 289757 T691 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 289757 T691 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 289757 T691 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 289758 T691 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 289758 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 289762 T691 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 289763 T691 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57582/solr
[junit4:junit4]   2> 289763 T691 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 289764 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 289765 T834 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10c63d4 name:ZooKeeperConnection Watcher:127.0.0.1:57582 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 289765 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 289767 T691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 289770 T691 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 289779 T836 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@125aba4 name:ZooKeeperConnection Watcher:127.0.0.1:57582/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 289779 T691 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 289782 T691 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 290709 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 290710 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"7",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":"shard3",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:44127_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:44127"}
[junit4:junit4]   2> 290714 T836 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290714 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290714 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290715 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290714 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290715 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290715 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290715 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290715 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290784 T691 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47226_
[junit4:junit4]   2> 290785 T691 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47226_
[junit4:junit4]   2> 290787 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 7)
[junit4:junit4]   2> 290787 T749 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290788 T720 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290788 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290788 T817 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290788 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290789 T713 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290789 T798 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290788 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290789 T781 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290789 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290789 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290788 T733 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290788 T836 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290788 T765 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 290790 T836 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290790 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290791 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 290802 T837 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 290802 T837 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 291555 T759 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 291555 T759 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:44127_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001 
[junit4:junit4]   2> 292220 T714 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 292221 T714 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"8",
[junit4:junit4]   2> 	  "numShards":"3",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:47226_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:47226"}
[junit4:junit4]   2> 292221 T714 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 292222 T714 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 292225 T836 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T798 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T733 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T817 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T713 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T720 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T749 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292225 T781 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 8)
[junit4:junit4]   2> 292803 T837 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/collection1
[junit4:junit4]   2> 292804 T837 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 292805 T837 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 292805 T837 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 292806 T837 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/collection1/'
[junit4:junit4]   2> 292807 T837 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/collection1/lib/README' to classloader
[junit4:junit4]   2> 292807 T837 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372244479832/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 292903 T837 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 293013 T837 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 293024 T837 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 293030 T837 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C1797 name=collection1 org.apache.solr.core.SolrCore@c5301b url=http://127.0.0.1:44127/collection1 node=127.0.0.1:44127_ C1797_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:44127_, base_url=http://127.0.0.1:44127}
[junit4:junit4]   2> 293556 T822 C1797 P44127 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:60386/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 293556 T822 C1797 P44127 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44127 START replicas=[http://127.0.0.1:60386/collection1/] nUpdates=100
[junit4:junit4]   2> 293557 T822 C1797 P44127 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 293557 T822 C1797 P44127 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 293557 T822 C1797 P44127 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 293557 T822 C1797 P44127 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 293557 T822 C1797 P44127 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 293558 T822 C1797 P44127 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:60386/collection1/. core=collection1
[junit4:junit4]   2> 293558 T822 C1797 P44127 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C1798 name=collection1 org.apache.solr.core.SolrCore@12f69d url=http://127.0.0.1:60386/collection1 node=127.0.0.1:60386_ C1798_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:60386_, base_url=http://127.0.0.1:60386, leader=true}
[junit4:junit4]   2> 293576 T758 C1798 P60386 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> ASYNC  NEW_CORE C1799 name=collection1 org.apache.solr.core.SolrCore@12f69d url=http://127.0.0.1:60386/collection1 node=127.0.0.1:60386_ C1799_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:60386_, base_url=http://127.0.0.1:60386, leader=true}
[junit4:junit4]   2> 293586 T761 C1799 P60386 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 293588 T761 C1799 P60386 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372244447187/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 293589 T761 C1799 P60386 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> ASYNC  NEW_CORE C1800 name=collection1 org.apache.solr.core.SolrCore@12f69d url=http://127.0.0.1:60386/collection1 node=127.0.0.1:60386_ C1800_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:60386_, base_url=http://127.0.0.1:60386, leader=true}
[junit4:junit4]   2> 293603 T761 C1800 P60386 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.Cha

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

      at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
[junit4:junit4]   2> 	        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:228)
[junit4:junit4]   2> 	        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:81)
[junit4:junit4]   2> 	        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
[junit4:junit4]   2> 	        at sun.nio.ch.SelectorImpl.selectNow(SelectorImpl.java:106)
[junit4:junit4]   2> 	        at org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:536)
[junit4:junit4]   2> 	        at org.eclipse.jetty.io.nio.SelectorManager$1.run(SelectorManager.java:290)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 	  74) Thread[id=885, name=qtp19618168-885 Acceptor1 SelectChannelConnector@127.0.0.1:48532, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at org.eclipse.jetty.server.nio.SelectChannelConnector.accept(SelectChannelConnector.java:102)
[junit4:junit4]   2> 	        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:938)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 	  75) Thread[id=897, name=searcherExecutor-747-thread-1, state=WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at sun.misc.Unsafe.park(Native Method)
[junit4:junit4]   2> 	        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
[junit4:junit4]   2> 	        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
[junit4:junit4]   2> 	        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 	  76) Thread[id=1014, name=qtp7745984-1014 Acceptor0 SelectChannelConnector@127.0.0.1:59918, state=BLOCKED, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at org.eclipse.jetty.server.nio.SelectChannelConnector.getConnection(SelectChannelConnector.java:160)
[junit4:junit4]   2> 	        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:934)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 	  77) Thread[id=1029, name=HashSessionScavenger-34, state=TIMED_WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at java.lang.Object.wait(Native Method)
[junit4:junit4]   2> 	        at java.util.TimerThread.mainLoop(Timer.java:552)
[junit4:junit4]   2> 	        at java.util.TimerThread.run(Timer.java:505)
[junit4:junit4]   2> 	  78) Thread[id=971, name=qtp18524539-971 Acceptor1 SelectChannelConnector@127.0.0.1:44127, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at org.eclipse.jetty.server.nio.SelectChannelConnector.accept(SelectChannelConnector.java:102)
[junit4:junit4]   2> 	        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:938)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 	  79) Thread[id=1030, name=qtp27226057-1030 Selector0, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at java.lang.Thread.isInterrupted(Native Method)
[junit4:junit4]   2> 	        at java.lang.Thread.isInterrupted(Thread.java:979)
[junit4:junit4]   2> 	        at java.nio.channels.spi.AbstractSelector.begin(AbstractSelector.java:215)
[junit4:junit4]   2> 	        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:80)
[junit4:junit4]   2> 	        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
[junit4:junit4]   2> 	        at sun.nio.ch.SelectorImpl.selectNow(SelectorImpl.java:106)
[junit4:junit4]   2> 	        at org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:536)
[junit4:junit4]   2> 	        at org.eclipse.jetty.io.nio.SelectorManager$1.run(SelectorManager.java:290)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 	  80) Thread[id=1043, name=searcherExecutor-810-thread-1, state=WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at sun.misc.Unsafe.park(Native Method)
[junit4:junit4]   2> 	        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
[junit4:junit4]   2> 	        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
[junit4:junit4]   2> 	        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
[junit4:junit4]   2> 	        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4]   2> 	        at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=en_MT, timezone=America/Argentina/Jujuy
[junit4:junit4]   2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_25 (32-bit)/cpus=8,threads=99,free=48940176,total=117878784
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestQueryTypes, ClusterStateTest, LeaderElectionIntegrationTest, TestStressLucene, TestMergePolicyConfig, TestRangeQuery, TestJmxMonitoredMap, TestBinaryResponseWriter, OutputWriterTest, SuggesterWFSTTest, TestComponentsName, TestCollationField, TestMultiCoreConfBootstrap, TestWordDelimiterFilterFactory, DisMaxRequestHandlerTest, SpellCheckComponentTest, TestCSVResponseWriter, TestRTGBase, TestReload, StandardRequestHandlerTest, CurrencyFieldXmlFileTest, TestSchemaVersionResource, DebugComponentTest, SolrIndexConfigTest, PathHierarchyTokenizerFactoryTest, TestRecovery, TestFastOutputStream, ShardRoutingCustomTest, TestSchemaNameResource, TestFieldTypeResource, UniqFieldsUpdateProcessorFactoryTest, TestSolrXMLSerializer, TestBM25SimilarityFactory, ZkNodePropsTest, TestLuceneMatchVersion, DirectSolrSpellCheckerTest, TestDistributedSearch, TestSerializedLuceneMatchVersion, TestPropInject, TimeZoneUtilsTest, HardAutoCommitTest, DocumentAnalysisRequestHandlerTest, SolrPluginUtilsTest, TestFoldingMultitermQuery, TestSolrQueryParserDefaultOperatorResource, TestCopyFieldCollectionResource, MultiTermTest, SpellPossibilityIteratorTest, DOMUtilTest, TestAtomicUpdateErrorCases, ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.seed=75147286676B0327 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_MT -Dtests.timezone=America/Argentina/Jujuy -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR   0.00s J1 | ChaosMonkeySafeLeaderTest (suite) <<<
[junit4:junit4]    > Throwable #1: java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([75147286676B0327]:0)
[junit4:junit4] Completed on J1 in 7226.97s, 1 test, 2 errors <<< FAILURES!

[...truncated 68 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 suite-level error, 1 error, 99 ignored (6 assumptions)

Total time: 147 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_25 -client -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message