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-4.x-Linux (32bit/jdk1.7.0_25) - Build # 6319 - Failure!
Date Mon, 01 Jul 2013 13:40:44 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6319/
Java: 32bit/jdk1.7.0_25 -server -XX:+UseG1GC

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([E2D880746982F611]: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([E2D880746982F611]:0)




Build Log:
[...truncated 10322 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4]   2> 438730 T2034 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 438734 T2034 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeySafeLeaderTest-1372678793079
[junit4:junit4]   2> 438735 T2034 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 438735 T2035 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 438835 T2034 oasc.ZkTestServer.run start zk server on port:40614
[junit4:junit4]   2> 438836 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 438848 T2041 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1292948 name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 438848 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 438849 T2034 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 438851 T2036 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f9a0827790000, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 438851 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 438854 T2043 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4abc6a name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 438854 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 438854 T2034 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 438856 T2034 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 438859 T2034 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 438861 T2034 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 438864 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 438865 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 438870 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 438871 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 438875 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 438876 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 438878 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 438878 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 438880 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 438880 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 438882 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 438882 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 438884 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 438884 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 438886 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 438886 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 438888 T2034 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 438888 T2034 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 438958 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 438960 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40019
[junit4:junit4]   2> 438961 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 438961 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 438962 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234
[junit4:junit4]   2> 438962 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/solr.xml
[junit4:junit4]   2> 438962 T2034 oasc.CoreContainer.<init> New CoreContainer 10690220
[junit4:junit4]   2> 438963 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/'
[junit4:junit4]   2> 438963 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/'
[junit4:junit4]   2> 439007 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 439007 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 439008 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 439008 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 439008 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 439008 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 439009 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 439009 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 439009 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 439010 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 439013 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 439013 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 439014 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 439014 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 439015 T2054 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@caec00 name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 439016 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 439017 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 439020 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 439021 T2056 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bb4a3c name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 439021 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 439022 T2034 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 439024 T2034 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 439025 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 439026 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40019_
[junit4:junit4]   2> 439027 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40019_
[junit4:junit4]   2> 439029 T2034 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 439032 T2034 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 439033 T2034 oasc.Overseer.start Overseer (id=89959877383356419-127.0.0.1:40019_-n_0000000000) starting
[junit4:junit4]   2> 439036 T2034 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 439039 T2058 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 439040 T2034 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 439041 T2034 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 439042 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 439043 T2057 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 439046 T2059 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 439046 T2059 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 440545 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 440546 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:40019_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40019"}
[junit4:junit4]   2> 440546 T2057 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 440546 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 440548 T2056 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> 441047 T2059 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/collection1
[junit4:junit4]   2> 441047 T2059 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 441048 T2059 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 441048 T2059 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 441050 T2059 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/collection1/'
[junit4:junit4]   2> 441050 T2059 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/collection1/lib/README' to classloader
[junit4:junit4]   2> 441051 T2059 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 441075 T2059 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 441105 T2059 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 441106 T2059 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 441109 T2059 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 441427 T2059 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 441427 T2059 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 441427 T2059 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 441432 T2059 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 441435 T2059 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 441444 T2059 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 441447 T2059 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 441450 T2059 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 441451 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 441451 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 441451 T2059 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 441452 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 441452 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 441452 T2059 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 441452 T2059 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372678793234/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/control/data/
[junit4:junit4]   2> 441452 T2059 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 441453 T2059 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 441453 T2059 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/control/data
[junit4:junit4]   2> 441453 T2059 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/control/data/index/
[junit4:junit4]   2> 441454 T2059 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 441454 T2059 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/control/data/index
[junit4:junit4]   2> 441477 T2059 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 441477 T2059 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 441479 T2059 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 441479 T2059 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 441479 T2059 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 441480 T2059 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 441480 T2059 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 441480 T2059 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 441480 T2059 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 441481 T2059 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 441481 T2059 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 441483 T2059 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 441486 T2059 oass.SolrIndexSearcher.<init> Opening Searcher@3c7871 main
[junit4:junit4]   2> 441486 T2059 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 441486 T2059 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 441489 T2060 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3c7871 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 441490 T2059 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 441490 T2059 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40019 collection:control_collection shard:shard1
[junit4:junit4]   2> 441491 T2059 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 441495 T2059 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 441496 T2059 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 441496 T2059 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 441497 T2059 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40019/collection1/
[junit4:junit4]   2> 441497 T2059 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 441497 T2059 oasc.SyncStrategy.syncToMe http://127.0.0.1:40019/collection1/ has no replicas
[junit4:junit4]   2> 441497 T2059 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40019/collection1/
[junit4:junit4]   2> 441497 T2059 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 442050 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 442054 T2056 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> 442102 T2059 oasc.ZkController.register We are http://127.0.0.1:40019/collection1/ and leader is http://127.0.0.1:40019/collection1/
[junit4:junit4]   2> 442102 T2059 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40019
[junit4:junit4]   2> 442102 T2059 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 442102 T2059 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 442102 T2059 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 442104 T2059 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 442105 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 442105 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 442105 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 442109 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 442111 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 442112 T2063 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@310b72 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 442112 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 442113 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 442114 T2034 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 442190 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 442192 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57964
[junit4:junit4]   2> 442193 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 442193 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 442193 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459
[junit4:junit4]   2> 442194 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/solr.xml
[junit4:junit4]   2> 442194 T2034 oasc.CoreContainer.<init> New CoreContainer 23155204
[junit4:junit4]   2> 442194 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/'
[junit4:junit4]   2> 442195 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/'
[junit4:junit4]   2> 442246 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 442247 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 442247 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 442247 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 442248 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 442248 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 442248 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 442249 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 442249 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 442249 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 442254 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 442254 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 442255 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 442255 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 442256 T2074 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d6f79f name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 442257 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 442258 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 442261 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 442262 T2076 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1889ca7 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 442262 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 442265 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 443267 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57964_
[junit4:junit4]   2> 443270 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57964_
[junit4:junit4]   2> 443273 T2063 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 443274 T2056 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 443274 T2076 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 443274 T2056 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> 443280 T2077 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 443280 T2077 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 443558 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 443558 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40019__collection1",
[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:40019_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40019"}
[junit4:junit4]   2> 443561 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:57964_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57964"}
[junit4:junit4]   2> 443561 T2057 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4]   2> 443561 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 443564 T2076 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> 443564 T2056 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> 443564 T2063 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> 444281 T2077 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/collection1
[junit4:junit4]   2> 444281 T2077 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 444282 T2077 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 444282 T2077 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 444283 T2077 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/collection1/'
[junit4:junit4]   2> 444283 T2077 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/collection1/lib/README' to classloader
[junit4:junit4]   2> 444283 T2077 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 444308 T2077 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 444339 T2077 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 444340 T2077 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 444344 T2077 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 444692 T2077 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 444692 T2077 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 444693 T2077 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 444698 T2077 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 444700 T2077 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 444709 T2077 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 444711 T2077 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 444713 T2077 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 444714 T2077 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 444714 T2077 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 444714 T2077 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 444715 T2077 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 444715 T2077 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 444715 T2077 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 444715 T2077 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372678796459/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1/
[junit4:junit4]   2> 444715 T2077 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 444716 T2077 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 444716 T2077 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1
[junit4:junit4]   2> 444716 T2077 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1/index/
[junit4:junit4]   2> 444717 T2077 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 444717 T2077 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1/index
[junit4:junit4]   2> 444719 T2077 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 444719 T2077 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 444721 T2077 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 444721 T2077 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 444722 T2077 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 444722 T2077 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 444722 T2077 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 444723 T2077 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 444723 T2077 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 444723 T2077 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 444724 T2077 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 444726 T2077 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 444728 T2077 oass.SolrIndexSearcher.<init> Opening Searcher@16e0b6d main
[junit4:junit4]   2> 444729 T2077 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 444729 T2077 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 444733 T2078 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16e0b6d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 444735 T2077 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 444735 T2077 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57964 collection:collection1 shard:shard1
[junit4:junit4]   2> 444736 T2077 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 444741 T2077 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 444742 T2077 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 444742 T2077 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 444743 T2077 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57964/collection1/
[junit4:junit4]   2> 444743 T2077 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 444743 T2077 oasc.SyncStrategy.syncToMe http://127.0.0.1:57964/collection1/ has no replicas
[junit4:junit4]   2> 444743 T2077 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57964/collection1/
[junit4:junit4]   2> 444743 T2077 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 445068 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 445073 T2056 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> 445073 T2076 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> 445073 T2063 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> 445097 T2077 oasc.ZkController.register We are http://127.0.0.1:57964/collection1/ and leader is http://127.0.0.1:57964/collection1/
[junit4:junit4]   2> 445097 T2077 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57964
[junit4:junit4]   2> 445098 T2077 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 445098 T2077 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 445098 T2077 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 445099 T2077 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 445100 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 445100 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 445100 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 445166 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 445167 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37080
[junit4:junit4]   2> 445168 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 445169 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 445169 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447
[junit4:junit4]   2> 445169 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/solr.xml
[junit4:junit4]   2> 445169 T2034 oasc.CoreContainer.<init> New CoreContainer 16498733
[junit4:junit4]   2> 445170 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/'
[junit4:junit4]   2> 445170 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/'
[junit4:junit4]   2> 445211 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 445211 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 445212 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 445212 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 445212 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 445213 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 445213 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 445213 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 445213 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 445214 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 445217 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 445217 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 445217 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 445218 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 445219 T2090 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@96690d name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 445220 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 445220 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 445223 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 445224 T2092 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@682ba3 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 445224 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 445226 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 446228 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37080_
[junit4:junit4]   2> 446229 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37080_
[junit4:junit4]   2> 446231 T2063 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> 446231 T2092 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 446231 T2076 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 446231 T2056 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 446231 T2076 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> 446232 T2056 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> 446232 T2063 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 446236 T2093 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 446236 T2093 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 446576 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 446577 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57964__collection1",
[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:57964_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57964"}
[junit4:junit4]   2> 446580 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:37080_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37080"}
[junit4:junit4]   2> 446580 T2057 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 446580 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 446583 T2092 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> 446583 T2056 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> 446583 T2063 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> 446583 T2076 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> 447237 T2093 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/collection1
[junit4:junit4]   2> 447237 T2093 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 447238 T2093 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 447238 T2093 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 447239 T2093 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/collection1/'
[junit4:junit4]   2> 447239 T2093 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/collection1/lib/README' to classloader
[junit4:junit4]   2> 447240 T2093 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 447272 T2093 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 447315 T2093 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 447316 T2093 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 447319 T2093 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 447650 T2093 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 447651 T2093 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 447651 T2093 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 447656 T2093 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 447659 T2093 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 447667 T2093 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 447670 T2093 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 447672 T2093 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 447673 T2093 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 447673 T2093 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 447673 T2093 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 447674 T2093 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 447674 T2093 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 447674 T2093 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 447675 T2093 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372678799447/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2/
[junit4:junit4]   2> 447675 T2093 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 447675 T2093 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 447676 T2093 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2
[junit4:junit4]   2> 447676 T2093 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2/index/
[junit4:junit4]   2> 447676 T2093 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 447676 T2093 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2/index
[junit4:junit4]   2> 447679 T2093 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 447679 T2093 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 447681 T2093 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 447681 T2093 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 447682 T2093 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 447682 T2093 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 447683 T2093 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 447683 T2093 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 447683 T2093 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 447684 T2093 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 447684 T2093 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 447686 T2093 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 447688 T2093 oass.SolrIndexSearcher.<init> Opening Searcher@194d235 main
[junit4:junit4]   2> 447689 T2093 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 447689 T2093 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 447693 T2094 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@194d235 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 447695 T2093 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 447695 T2093 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37080 collection:collection1 shard:shard2
[junit4:junit4]   2> 447696 T2093 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 447699 T2093 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 447700 T2093 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 447701 T2093 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 447701 T2093 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37080/collection1/
[junit4:junit4]   2> 447701 T2093 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 447701 T2093 oasc.SyncStrategy.syncToMe http://127.0.0.1:37080/collection1/ has no replicas
[junit4:junit4]   2> 447701 T2093 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37080/collection1/
[junit4:junit4]   2> 447701 T2093 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 448088 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 448096 T2056 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> 448096 T2092 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> 448096 T2076 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> 448096 T2063 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> 448105 T2093 oasc.ZkController.register We are http://127.0.0.1:37080/collection1/ and leader is http://127.0.0.1:37080/collection1/
[junit4:junit4]   2> 448105 T2093 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37080
[junit4:junit4]   2> 448106 T2093 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 448106 T2093 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 448106 T2093 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 448126 T2093 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 448127 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 448128 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 448128 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 448193 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 448195 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54425
[junit4:junit4]   2> 448196 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 448196 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 448197 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475
[junit4:junit4]   2> 448197 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/solr.xml
[junit4:junit4]   2> 448197 T2034 oasc.CoreContainer.<init> New CoreContainer 16517853
[junit4:junit4]   2> 448198 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/'
[junit4:junit4]   2> 448198 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/'
[junit4:junit4]   2> 448239 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 448239 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 448240 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 448240 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 448240 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 448241 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 448241 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 448241 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 448241 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 448242 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 448245 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 448245 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 448245 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 448246 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 448248 T2106 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11bba13 name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 448249 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 448250 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 448255 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 448256 T2108 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@939bb6 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 448256 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 448259 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 449262 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54425_
[junit4:junit4]   2> 449263 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54425_
[junit4:junit4]   2> 449264 T2063 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> 449264 T2092 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 449265 T2092 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> 449265 T2076 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 449265 T2056 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 449265 T2108 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 449265 T2056 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> 449265 T2076 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> 449266 T2063 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 449270 T2109 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 449270 T2109 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 449602 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 449602 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37080__collection1",
[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:37080_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37080"}
[junit4:junit4]   2> 449605 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:54425_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54425"}
[junit4:junit4]   2> 449605 T2057 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 449605 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4]   2> 449607 T2056 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> 449607 T2108 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> 449607 T2092 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> 449607 T2076 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> 449608 T2063 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> 450271 T2109 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/collection1
[junit4:junit4]   2> 450271 T2109 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 450272 T2109 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 450272 T2109 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 450273 T2109 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/collection1/'
[junit4:junit4]   2> 450273 T2109 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/collection1/lib/README' to classloader
[junit4:junit4]   2> 450273 T2109 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 450302 T2109 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 450330 T2109 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 450332 T2109 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 450335 T2109 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 450657 T2109 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 450657 T2109 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 450658 T2109 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 450663 T2109 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 450665 T2109 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 450675 T2109 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 450678 T2109 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 450681 T2109 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 450681 T2109 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 450682 T2109 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 450682 T2109 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 450683 T2109 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 450683 T2109 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 450683 T2109 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 450684 T2109 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372678802475/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3/
[junit4:junit4]   2> 450684 T2109 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 450684 T2109 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 450685 T2109 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3
[junit4:junit4]   2> 450685 T2109 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3/index/
[junit4:junit4]   2> 450686 T2109 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 450686 T2109 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3/index
[junit4:junit4]   2> 450689 T2109 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 450690 T2109 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 450691 T2109 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 450691 T2109 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 450692 T2109 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 450692 T2109 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 450693 T2109 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 450693 T2109 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 450693 T2109 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 450694 T2109 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 450694 T2109 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 450696 T2109 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 450699 T2109 oass.SolrIndexSearcher.<init> Opening Searcher@1b7ee3b main
[junit4:junit4]   2> 450699 T2109 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 450699 T2109 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 450706 T2110 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b7ee3b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 450708 T2109 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 450709 T2109 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54425 collection:collection1 shard:shard3
[junit4:junit4]   2> 450709 T2109 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4]   2> 450714 T2109 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 450716 T2109 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 450716 T2109 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 450716 T2109 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54425/collection1/
[junit4:junit4]   2> 450716 T2109 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 450716 T2109 oasc.SyncStrategy.syncToMe http://127.0.0.1:54425/collection1/ has no replicas
[junit4:junit4]   2> 450716 T2109 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54425/collection1/
[junit4:junit4]   2> 450716 T2109 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4]   2> 451111 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 451116 T2056 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> 451116 T2076 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> 451116 T2092 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> 451116 T2108 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> 451116 T2063 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> 451120 T2109 oasc.ZkController.register We are http://127.0.0.1:54425/collection1/ and leader is http://127.0.0.1:54425/collection1/
[junit4:junit4]   2> 451120 T2109 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54425
[junit4:junit4]   2> 451120 T2109 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 451121 T2109 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 451121 T2109 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 451122 T2109 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 451123 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 451123 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 451124 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 451188 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 451190 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34291
[junit4:junit4]   2> 451191 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 451191 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 451192 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471
[junit4:junit4]   2> 451192 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/solr.xml
[junit4:junit4]   2> 451192 T2034 oasc.CoreContainer.<init> New CoreContainer 26368738
[junit4:junit4]   2> 451193 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/'
[junit4:junit4]   2> 451193 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/'
[junit4:junit4]   2> 451233 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 451234 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 451234 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 451234 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 451235 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 451235 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 451235 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 451235 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 451236 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 451236 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 451239 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 451239 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 451240 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 451240 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 451242 T2122 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1128580 name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 451242 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 451243 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 451246 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 451247 T2124 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@feeac8 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 451248 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 451250 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 452252 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34291_
[junit4:junit4]   2> 452254 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34291_
[junit4:junit4]   2> 452255 T2063 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> 452255 T2076 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 452255 T2056 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 452255 T2108 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> 452256 T2124 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 452256 T2056 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> 452256 T2076 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> 452255 T2092 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 452257 T2092 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> 452257 T2063 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 452257 T2108 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 452263 T2125 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 452264 T2125 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 452620 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 452621 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:54425__collection1",
[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:54425_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54425"}
[junit4:junit4]   2> 452624 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:34291_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34291"}
[junit4:junit4]   2> 452625 T2057 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 452625 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 452629 T2056 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> 452630 T2076 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> 452630 T2063 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> 452630 T2108 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> 452630 T2092 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> 452630 T2124 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> 453265 T2125 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/collection1
[junit4:junit4]   2> 453266 T2125 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 453266 T2125 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 453267 T2125 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 453268 T2125 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/collection1/'
[junit4:junit4]   2> 453268 T2125 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/collection1/lib/README' to classloader
[junit4:junit4]   2> 453269 T2125 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 453294 T2125 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 453323 T2125 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 453324 T2125 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 453328 T2125 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 453666 T2125 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 453666 T2125 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 453667 T2125 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 453672 T2125 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 453674 T2125 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 453685 T2125 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 453691 T2125 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 453694 T2125 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 453694 T2125 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 453695 T2125 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 453695 T2125 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 453696 T2125 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 453696 T2125 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 453696 T2125 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 453696 T2125 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372678805471/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty4/
[junit4:junit4]   2> 453697 T2125 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 453697 T2125 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 453698 T2125 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty4
[junit4:junit4]   2> 453698 T2125 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty4/index/
[junit4:junit4]   2> 453699 T2125 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 453700 T2125 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty4/index
[junit4:junit4]   2> 453717 T2125 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 453717 T2125 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 453719 T2125 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 453719 T2125 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 453720 T2125 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 453720 T2125 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 453721 T2125 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 453721 T2125 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 453721 T2125 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 453722 T2125 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 453722 T2125 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 453725 T2125 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 453728 T2125 oass.SolrIndexSearcher.<init> Opening Searcher@56df5d main
[junit4:junit4]   2> 453728 T2125 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 453728 T2125 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 453733 T2126 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@56df5d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 453736 T2125 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 453736 T2125 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34291 collection:collection1 shard:shard1
[junit4:junit4]   2> 453738 T2125 oasc.ZkController.register We are http://127.0.0.1:34291/collection1/ and leader is http://127.0.0.1:57964/collection1/
[junit4:junit4]   2> 453738 T2125 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34291
[junit4:junit4]   2> 453738 T2125 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 453738 T2125 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C415 name=collection1 org.apache.solr.core.SolrCore@1f020d6 url=http://127.0.0.1:34291/collection1 node=127.0.0.1:34291_ C415_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:34291_, base_url=http://127.0.0.1:34291}
[junit4:junit4]   2> 453738 T2127 C415 P34291 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 453739 T2125 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 453739 T2127 C415 P34291 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 453739 T2127 C415 P34291 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 453740 T2127 C415 P34291 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 453740 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 453740 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 453740 T2127 C415 P34291 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 453741 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 453745 T2069 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:34291__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 453811 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 453813 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55276
[junit4:junit4]   2> 453814 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 453814 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 453814 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088
[junit4:junit4]   2> 453814 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/solr.xml
[junit4:junit4]   2> 453815 T2034 oasc.CoreContainer.<init> New CoreContainer 17290247
[junit4:junit4]   2> 453815 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/'
[junit4:junit4]   2> 453815 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/'
[junit4:junit4]   2> 453859 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 453859 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 453859 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 453860 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 453860 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 453860 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 453861 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 453861 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 453861 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 453862 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 453865 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 453865 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 453866 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 453866 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 453867 T2139 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@775f8f name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 453868 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 453869 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 453871 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 453872 T2141 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@196a911 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 453872 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 453874 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 454135 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 454135 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34291__collection1",
[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:34291_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34291"}
[junit4:junit4]   2> 454138 T2056 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> 454138 T2108 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> 454138 T2063 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> 454138 T2124 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> 454138 T2092 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> 454138 T2141 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> 454138 T2076 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> 454745 T2069 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:34291__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 454745 T2069 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:34291__collection1&state=recovering&nodeName=127.0.0.1:34291_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000 
[junit4:junit4]   2> 454876 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55276_
[junit4:junit4]   2> 454877 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55276_
[junit4:junit4]   2> 454879 T2063 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> 454879 T2108 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> 454880 T2141 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> 454880 T2056 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454880 T2124 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454880 T2124 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> 454880 T2076 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454880 T2092 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454880 T2056 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> 454881 T2092 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> 454881 T2076 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> 454881 T2063 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454882 T2108 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454883 T2141 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4]   2> 454888 T2142 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 454889 T2142 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 455641 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 455642 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:55276_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55276"}
[junit4:junit4]   2> 455642 T2057 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 455642 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4]   2> 455645 T2076 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> 455645 T2141 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> 455645 T2063 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> 455645 T2108 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> 455645 T2092 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> 455645 T2056 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> 455645 T2124 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> 455894 T2142 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/collection1
[junit4:junit4]   2> 455894 T2142 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 455895 T2142 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 455895 T2142 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 455896 T2142 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/collection1/'
[junit4:junit4]   2> 455897 T2142 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/collection1/lib/README' to classloader
[junit4:junit4]   2> 455897 T2142 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 455931 T2142 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 455970 T2142 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 455971 T2142 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 455975 T2142 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 456410 T2142 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 456411 T2142 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 456411 T2142 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 456418 T2142 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 456420 T2142 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 456432 T2142 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 456436 T2142 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 456439 T2142 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 456440 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 456440 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 456441 T2142 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 456441 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 456441 T2142 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 456442 T2142 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 456442 T2142 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372678808088/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty5/
[junit4:junit4]   2> 456442 T2142 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 456443 T2142 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 456443 T2142 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty5
[junit4:junit4]   2> 456443 T2142 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty5/index/
[junit4:junit4]   2> 456443 T2142 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 456444 T2142 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty5/index
[junit4:junit4]   2> 456517 T2142 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 456518 T2142 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 456519 T2142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 456520 T2142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 456520 T2142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 456521 T2142 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 456522 T2142 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 456522 T2142 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 456522 T2142 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 456523 T2142 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 456524 T2142 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 456527 T2142 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 456534 T2142 oass.SolrIndexSearcher.<init> Opening Searcher@bf2a8d main
[junit4:junit4]   2> 456535 T2142 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 456535 T2142 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 456542 T2143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bf2a8d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 456545 T2142 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 456545 T2142 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55276 collection:collection1 shard:shard2
[junit4:junit4]   2> 456547 T2142 oasc.ZkController.register We are http://127.0.0.1:55276/collection1/ and leader is http://127.0.0.1:37080/collection1/
[junit4:junit4]   2> 456548 T2142 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55276
[junit4:junit4]   2> 456548 T2142 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 456548 T2142 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C416 name=collection1 org.apache.solr.core.SolrCore@74abe4 url=http://127.0.0.1:55276/collection1 node=127.0.0.1:55276_ C416_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55276_, base_url=http://127.0.0.1:55276}
[junit4:junit4]   2> 456548 T2144 C416 P55276 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 456549 T2142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 456549 T2144 C416 P55276 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 456550 T2144 C416 P55276 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 456550 T2144 C416 P55276 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 456551 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 456551 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 456551 T2144 C416 P55276 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 456552 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 456563 T2087 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:55276__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 456639 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 456640 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37650
[junit4:junit4]   2> 456642 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 456642 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 456642 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901
[junit4:junit4]   2> 456643 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/solr.xml
[junit4:junit4]   2> 456643 T2034 oasc.CoreContainer.<init> New CoreContainer 10220052
[junit4:junit4]   2> 456643 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/'
[junit4:junit4]   2> 456644 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/'
[junit4:junit4]   2> 456701 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 456702 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 456702 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 456704 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 456704 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 456705 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 456705 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 456705 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 456706 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 456706 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 456711 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 456712 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 456712 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 456713 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 456714 T2156 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13b9a35 name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 456715 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 456716 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 456719 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 456720 T2158 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1437e73 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 456720 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 456722 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C417 name=collection1 org.apache.solr.core.SolrCore@1f020d6 url=http://127.0.0.1:34291/collection1 node=127.0.0.1:34291_ C417_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:34291_, base_url=http://127.0.0.1:34291}
[junit4:junit4]   2> 456746 T2127 C417 P34291 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57964/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 456747 T2127 C417 P34291 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34291 START replicas=[http://127.0.0.1:57964/collection1/] nUpdates=100
[junit4:junit4]   2> 456747 T2127 C417 P34291 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 456748 T2127 C417 P34291 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 456748 T2127 C417 P34291 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 456748 T2127 C417 P34291 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 456748 T2127 C417 P34291 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 456748 T2127 C417 P34291 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57964/collection1/. core=collection1
[junit4:junit4]   2> 456749 T2127 C417 P34291 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C418 name=collection1 org.apache.solr.core.SolrCore@9d3a48 url=http://127.0.0.1:57964/collection1 node=127.0.0.1:57964_ C418_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57964_, base_url=http://127.0.0.1:57964, leader=true}
[junit4:junit4]   2> 456755 T2072 C418 P57964 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> 456759 T2071 C418 P57964 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 456762 T2071 C418 P57964 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 456763 T2071 C418 P57964 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 456763 T2071 C418 P57964 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 456764 T2071 C418 P57964 oass.SolrIndexSearcher.<init> Opening Searcher@9782b4 realtime
[junit4:junit4]   2> 456764 T2071 C418 P57964 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 456765 T2071 C418 P57964 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 6
[junit4:junit4]   2> 456766 T2127 C417 P34291 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 456766 T2127 C417 P34291 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 456768 T2069 C418 P57964 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 456768 T2069 C418 P57964 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 456769 T2127 C417 P34291 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 456769 T2127 C417 P34291 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 456770 T2127 C417 P34291 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 456770 T2127 C417 P34291 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 456771 T2127 C417 P34291 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 457149 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 457150 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:55276__collection1",
[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:55276_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55276"}
[junit4:junit4]   2> 457152 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34291__collection1",
[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:34291_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34291"}
[junit4:junit4]   2> 457155 T2141 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> 457156 T2076 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> 457156 T2092 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> 457156 T2056 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> 457156 T2158 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> 457156 T2063 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> 457156 T2108 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> 457156 T2124 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> 457563 T2087 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:55276__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 457564 T2087 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:55276__collection1&state=recovering&nodeName=127.0.0.1:55276_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001 
[junit4:junit4]   2> 457728 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37650_
[junit4:junit4]   2> 457730 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37650_
[junit4:junit4]   2> 457731 T2141 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> 457731 T2108 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> 457731 T2092 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457731 T2076 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457731 T2158 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457731 T2063 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> 457732 T2158 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> 457732 T2124 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457732 T2076 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> 457731 T2092 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> 457733 T2108 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457732 T2141 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457732 T2124 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> 457733 T2063 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457732 T2056 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4]   2> 457734 T2056 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> 457738 T2160 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 457738 T2160 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 458661 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 458662 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:37650_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37650"}
[junit4:junit4]   2> 458662 T2057 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 458663 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4]   2> 458666 T2141 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> 458666 T2056 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> 458666 T2108 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> 458666 T2063 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> 458666 T2092 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> 458666 T2158 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> 458666 T2124 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> 458666 T2076 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> 458740 T2160 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/collection1
[junit4:junit4]   2> 458740 T2160 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 458740 T2160 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 458741 T2160 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 458741 T2160 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/collection1/'
[junit4:junit4]   2> 458742 T2160 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/collection1/lib/README' to classloader
[junit4:junit4]   2> 458742 T2160 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 458774 T2160 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 458810 T2160 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 458811 T2160 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 458816 T2160 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 459183 T2160 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 459183 T2160 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 459183 T2160 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 459189 T2160 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 459191 T2160 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 459199 T2160 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 459203 T2160 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 459206 T2160 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 459207 T2160 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 459207 T2160 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 459207 T2160 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 459208 T2160 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 459208 T2160 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 459208 T2160 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 459208 T2160 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372678810901/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty6/
[junit4:junit4]   2> 459208 T2160 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 459209 T2160 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 459209 T2160 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty6
[junit4:junit4]   2> 459209 T2160 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty6/index/
[junit4:junit4]   2> 459210 T2160 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 459210 T2160 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty6/index
[junit4:junit4]   2> 459213 T2160 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 459213 T2160 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 459215 T2160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 459215 T2160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 459216 T2160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 459216 T2160 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 459216 T2160 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 459217 T2160 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 459217 T2160 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 459217 T2160 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 459218 T2160 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 459220 T2160 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 459222 T2160 oass.SolrIndexSearcher.<init> Opening Searcher@1ef1b06 main
[junit4:junit4]   2> 459223 T2160 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 459223 T2160 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 459227 T2161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ef1b06 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 459229 T2160 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 459229 T2160 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37650 collection:collection1 shard:shard3
[junit4:junit4]   2> 459231 T2160 oasc.ZkController.register We are http://127.0.0.1:37650/collection1/ and leader is http://127.0.0.1:54425/collection1/
[junit4:junit4]   2> 459231 T2160 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37650
[junit4:junit4]   2> 459231 T2160 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 459231 T2160 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C419 name=collection1 org.apache.solr.core.SolrCore@5562c4 url=http://127.0.0.1:37650/collection1 node=127.0.0.1:37650_ C419_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:37650_, base_url=http://127.0.0.1:37650}
[junit4:junit4]   2> 459232 T2162 C419 P37650 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 459232 T2160 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 459232 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 459232 T2162 C419 P37650 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 459233 T2162 C419 P37650 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 459233 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 459233 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 459233 T2162 C419 P37650 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 459234 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 459237 T2101 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:37650__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 459319 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 459320 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38044
[junit4:junit4]   2> 459321 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 459322 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 459322 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581
[junit4:junit4]   2> 459322 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/solr.xml
[junit4:junit4]   2> 459323 T2034 oasc.CoreContainer.<init> New CoreContainer 23782478
[junit4:junit4]   2> 459323 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/'
[junit4:junit4]   2> 459323 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/'
[junit4:junit4]   2> 459368 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 459368 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 459368 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 459369 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 459369 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 459369 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 459370 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 459370 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 459370 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 459371 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 459374 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 459374 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 459374 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 459375 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 459376 T2174 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bbd3c4 name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 459377 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 459378 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 459380 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 459382 T2176 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b2f54b name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 459382 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 459384 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C420 name=collection1 org.apache.solr.core.SolrCore@74abe4 url=http://127.0.0.1:55276/collection1 node=127.0.0.1:55276_ C420_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:55276_, base_url=http://127.0.0.1:55276}
[junit4:junit4]   2> 459565 T2144 C420 P55276 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:37080/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 459565 T2144 C420 P55276 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55276 START replicas=[http://127.0.0.1:37080/collection1/] nUpdates=100
[junit4:junit4]   2> 459566 T2144 C420 P55276 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 459567 T2144 C420 P55276 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 459567 T2144 C420 P55276 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 459567 T2144 C420 P55276 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 459568 T2144 C420 P55276 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 459568 T2144 C420 P55276 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:37080/collection1/. core=collection1
[junit4:junit4]   2> 459568 T2144 C420 P55276 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C421 name=collection1 org.apache.solr.core.SolrCore@b3b11e url=http://127.0.0.1:37080/collection1 node=127.0.0.1:37080_ C421_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:37080_, base_url=http://127.0.0.1:37080, leader=true}
[junit4:junit4]   2> 459576 T2085 C421 P37080 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 459576 T2087 C421 P37080 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 459579 T2087 C421 P37080 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 459579 T2087 C421 P37080 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 459579 T2087 C421 P37080 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 459580 T2087 C421 P37080 oass.SolrIndexSearcher.<init> Opening Searcher@118c1a2 realtime
[junit4:junit4]   2> 459580 T2087 C421 P37080 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 459580 T2087 C421 P37080 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 4
[junit4:junit4]   2> 459581 T2144 C420 P55276 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 459581 T2144 C420 P55276 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 459583 T2086 C421 P37080 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 459583 T2086 C421 P37080 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 459583 T2144 C420 P55276 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 459584 T2144 C420 P55276 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 459584 T2144 C420 P55276 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 459584 T2144 C420 P55276 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 459585 T2144 C420 P55276 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 460170 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 460171 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37650__collection1",
[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:37650_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37650"}
[junit4:junit4]   2> 460175 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:55276__collection1",
[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:55276_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55276"}
[junit4:junit4]   2> 460179 T2056 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> 460179 T2076 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> 460180 T2108 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> 460180 T2063 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> 460180 T2092 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> 460180 T2176 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> 460179 T2141 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> 460180 T2124 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> 460180 T2158 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> 460238 T2101 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:37650__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4]   2> 460238 T2101 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:37650__collection1&state=recovering&nodeName=127.0.0.1:37650_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001 
[junit4:junit4]   2> 460386 T2034 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38044_
[junit4:junit4]   2> 460387 T2034 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38044_
[junit4:junit4]   2> 460388 T2141 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> 460389 T2063 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> 460389 T2158 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460389 T2124 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460389 T2108 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> 460389 T2176 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460389 T2124 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> 460389 T2092 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460389 T2056 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460389 T2158 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> 460389 T2076 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460390 T2056 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> 460391 T2108 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460390 T2092 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> 460390 T2063 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460390 T2176 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> 460390 T2141 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4]   2> 460391 T2076 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> 460396 T2178 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 460397 T2178 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 461684 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 461685 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:38044_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38044"}
[junit4:junit4]   2> 461685 T2057 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4]   2> 461685 T2057 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 461688 T2124 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> 461688 T2141 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> 461689 T2076 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> 461688 T2158 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> 461689 T2092 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> 461689 T2176 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> 461689 T2108 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> 461689 T2063 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> 461689 T2056 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>  C419_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:37650_, base_url=http://127.0.0.1:37650}
[junit4:junit4]   2> 462239 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54425/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 462239 T2162 C419 P37650 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:37650 START replicas=[http://127.0.0.1:54425/collection1/] nUpdates=100
[junit4:junit4]   2> 462240 T2162 C419 P37650 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 462240 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 462241 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 462241 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 462241 T2162 C419 P37650 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 462241 T2162 C419 P37650 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54425/collection1/. core=collection1
[junit4:junit4]   2> 462241 T2162 C419 P37650 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C422 name=collection1 org.apache.solr.core.SolrCore@10c87d1 url=http://127.0.0.1:54425/collection1 node=127.0.0.1:54425_ C422_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54425_, base_url=http://127.0.0.1:54425, leader=true}
[junit4:junit4]   2> 462246 T2102 C422 P54425 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 462249 T2103 C422 P54425 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 462251 T2103 C422 P54425 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 462252 T2103 C422 P54425 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 462252 T2103 C422 P54425 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4]   2> 462252 T2103 C422 P54425 oass.SolrIndexSearcher.<init> Opening Searcher@1f01955 realtime
[junit4:junit4]   2> 462253 T2103 C422 P54425 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 462253 T2103 C422 P54425 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 4
[junit4:junit4]   2> 462254 T2162 C419 P37650 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 462254 T2162 C419 P37650 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 462258 T2101 C422 P54425 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 462258 T2101 C422 P54425 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 462259 T2162 C419 P37650 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 462259 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 462260 T2162 C419 P37650 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 462260 T2162 C419 P37650 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 462261 T2162 C419 P37650 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 462399 T2178 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/collection1
[junit4:junit4]   2> 462399 T2178 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 462399 T2178 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 462399 T2178 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 462400 T2178 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/collection1/'
[junit4:junit4]   2> 462401 T2178 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/collection1/lib/README' to classloader
[junit4:junit4]   2> 462401 T2178 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 462427 T2178 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 462469 T2178 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 462471 T2178 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 462476 T2178 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 462878 T2178 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 462878 T2178 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 462879 T2178 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 462886 T2178 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 462888 T2178 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 462896 T2178 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 462899 T2178 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 462902 T2178 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 462903 T2178 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 462903 T2178 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 462904 T2178 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 462904 T2178 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 462905 T2178 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 462905 T2178 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 462905 T2178 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372678813581/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty7/
[junit4:junit4]   2> 462905 T2178 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@17d9933
[junit4:junit4]   2> 462906 T2178 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 462906 T2178 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty7
[junit4:junit4]   2> 462906 T2178 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty7/index/
[junit4:junit4]   2> 462907 T2178 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 462907 T2178 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty7/index
[junit4:junit4]   2> 462911 T2178 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372678793078/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4]   2> 462911 T2178 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 462913 T2178 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 462913 T2178 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 462914 T2178 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 462914 T2178 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 462915 T2178 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 462915 T2178 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 462917 T2178 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 462918 T2178 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 462918 T2178 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 462921 T2178 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 462924 T2178 oass.SolrIndexSearcher.<init> Opening Searcher@1f941e9 main
[junit4:junit4]   2> 462925 T2178 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 462925 T2178 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 462931 T2180 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f941e9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 462933 T2178 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 462933 T2178 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38044 collection:collection1 shard:shard1
[junit4:junit4]   2> 462935 T2178 oasc.ZkController.register We are http://127.0.0.1:38044/collection1/ and leader is http://127.0.0.1:57964/collection1/
[junit4:junit4]   2> 462935 T2178 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38044
[junit4:junit4]   2> 462935 T2178 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 462936 T2178 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C423 name=collection1 org.apache.solr.core.SolrCore@c3f27e url=http://127.0.0.1:38044/collection1 node=127.0.0.1:38044_ C423_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:38044_, base_url=http://127.0.0.1:38044}
[junit4:junit4]   2> 462936 T2181 C423 P38044 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 462936 T2178 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 462936 T2181 C423 P38044 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 462937 T2181 C423 P38044 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 462937 T2181 C423 P38044 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 462937 T2034 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 462938 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 462938 T2181 C423 P38044 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 462938 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 462943 T2069 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:38044__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 463017 T2034 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 463020 T2034 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55802
[junit4:junit4]   2> 463020 T2034 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 463021 T2034 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 463021 T2034 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1372678817286
[junit4:junit4]   2> 463021 T2034 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1372678817286/solr.xml
[junit4:junit4]   2> 463021 T2034 oasc.CoreContainer.<init> New CoreContainer 26210979
[junit4:junit4]   2> 463022 T2034 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1372678817286/'
[junit4:junit4]   2> 463022 T2034 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty8-1372678817286/'
[junit4:junit4]   2> 463067 T2034 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 463068 T2034 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 463068 T2034 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 463068 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 463069 T2034 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 463069 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 463069 T2034 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 463069 T2034 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 463070 T2034 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 463070 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 463073 T2034 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 463073 T2034 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40614/solr
[junit4:junit4]   2> 463074 T2034 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 463074 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 463075 T2193 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@131ed3b name:ZooKeeperConnection Watcher:127.0.0.1:40614 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 463076 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 463077 T2034 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 463080 T2034 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 463081 T2195 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b9f853 name:ZooKeeperConnection Watcher:127.0.0.1:40614/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 463081 T2034 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 463084 T2034 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 463194 T2057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 463195 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37650__collection1",
[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:37650_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37650"}
[junit4:junit4]   2> 463198 T2057 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:38044__collection1",
[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:38044_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38044"}
[junit4:junit4]   2> 463201 T2195 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> 463201 T2124 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has

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

rk(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> 	  80) Thread[id=2220, name=qtp31957923-2220 Selector1, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at sun.nio.ch.IOUtil.drain(Native Method)
[junit4:junit4]   2> 	        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:92)
[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> 	  81) Thread[id=2253, name=Thread-772, state=WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at java.lang.Object.wait(Native Method)
[junit4:junit4]   2> 	        at java.lang.Object.wait(Object.java:503)
[junit4:junit4]   2> 	        at org.apache.solr.core.CloserThread.run(CoreContainer.java:1304)
[junit4:junit4]   2> 	  82) Thread[id=2251, name=searcherExecutor-1024-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> 	  83) Thread[id=2114, name=qtp31921455-2114 Selector1, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> 	        at sun.nio.ch.IOUtil.drain(Native Method)
[junit4:junit4]   2> 	        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:92)
[junit4:junit4]   2> 	        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
[junit4:junit4]   2> 	        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
[junit4:junit4]   2> 	        at org.eclipse.jetty.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:569)
[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> 	  84) Thread[id=2287, name=commitScheduler-1015-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.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1079)
[junit4:junit4]   2> 	        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
[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=Lucene42: {range_facet_l=Pulsing41(freqCutoff=3 minBlockSize=29 maxBlockSize=126), text=PostingsFormat(name=Memory doPackFST= false), _version_=Pulsing41(freqCutoff=3 minBlockSize=29 maxBlockSize=126), rnd_b=Pulsing41(freqCutoff=4 minBlockSize=29 maxBlockSize=126), intDefault=Pulsing41(freqCutoff=3 minBlockSize=29 maxBlockSize=126), timestamp=Pulsing41(freqCutoff=3 minBlockSize=29 maxBlockSize=126), id=Pulsing41(freqCutoff=4 minBlockSize=29 maxBlockSize=126), a_t=Pulsing41(freqCutoff=3 minBlockSize=29 maxBlockSize=126), range_facet_sl=PostingsFormat(name=Memory doPackFST= false), range_facet_si=PostingsFormat(name=Memory doPackFST= true), other_tl1=Pulsing41(freqCutoff=3 minBlockSize=29 maxBlockSize=126), multiDefault=PostingsFormat(name=Memory doPackFST= true), a_si=PostingsFormat(name=Memory doPackFST= true)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=fr, timezone=America/Louisville
[junit4:junit4]   2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_25 (32-bit)/cpus=8,threads=101,free=275923568,total=468713472
[junit4:junit4]   2> NOTE: All tests run in this JVM: [SolrInfoMBeanTest, TestFieldTypeCollectionResource, TestSolrQueryParser, TestUniqueKeyFieldResource, TestPluginEnable, UpdateRequestProcessorFactoryTest, TestCoreContainer, DocumentBuilderTest, ClusterStateUpdateTest, SolrIndexSplitterTest, TestDefaultSearchFieldResource, TestFuzzyAnalyzedSuggestions, TestCharFilters, FastVectorHighlighterTest, TestSolrQueryParserResource, SoftAutoCommitTest, TestFastWriter, CircularListTest, PreAnalyzedUpdateProcessorTest, TestSchemaNameResource, DateFieldTest, LegacyHTMLStripCharFilterTest, SuggesterFSTTest, ZkControllerTest, BasicFunctionalityTest, TestSolrQueryParserDefaultOperatorResource, TestIBSimilarityFactory, TestMaxScoreQueryParser, SystemInfoHandlerTest, MoreLikeThisHandlerTest, StatelessScriptUpdateProcessorFactoryTest, ChaosMonkeyNothingIsSafeTest, FileBasedSpellCheckerTest, ExternalFileFieldSortTest, LeaderElectionTest, TestStressVersions, TestFunctionQuery, SchemaVersionSpecificBehaviorTest, TestFieldResource, TestFieldTypeResource, ReturnFieldsTest, LoggingHandlerTest, OverseerTest, TermVectorComponentTest, TestPropInjectDefaults, SynonymTokenizerTest, TestDocSet, ParsingFieldUpdateProcessorsTest, TestWriterPerf, TestTrie, CSVRequestHandlerTest, TestQueryUtils, TestSolrDeletionPolicy2, TestLMDirichletSimilarityFactory, MBeansHandlerTest, TestSolrIndexConfig, UUIDFieldTest, TestFaceting, TestSweetSpotSimilarityFactory, TestRealTimeGet, DistributedTermsComponentTest, RegexBoostProcessorTest, TestDocumentBuilder, ShowFileRequestHandlerTest, SimpleFacetsTest, UnloadDistributedZkTest, TestSolrCoreProperties, PrimitiveFieldTypeTest, SolrCoreTest, TestPerFieldSimilarity, TestLRUCache, DistributedQueryElevationComponentTest, DirectUpdateHandlerOptimizeTest, ChaosMonkeySafeLeaderTest]
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.seed=E2D880746982F611 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=fr -Dtests.timezone=America/Louisville -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR   0.00s J0 | ChaosMonkeySafeLeaderTest (suite) <<<
[junit4:junit4]    > Throwable #1: java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([E2D880746982F611]:0)
[junit4:junit4] Completed on J0 in 7225.59s, 1 test, 2 errors <<< FAILURES!

[...truncated 11 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1248: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:892: There were test failures: 299 suites, 1290 tests, 1 suite-level error, 1 error, 13 ignored (7 assumptions)

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



Mime
View raw message