You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/30 22:47:51 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.6.0) - Build # 595 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/595/
Java: 64bit/jdk1.6.0 -XX:+UseCompressedOops -XX:+UseParallelGC
2 tests failed.
FAILED: 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([E193A21E9B15C7E2]:0)
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([E193A21E9B15C7E2]:0)
Build Log:
[...truncated 9137 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest
[junit4:junit4] 2> 2553006 T4563 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 2553015 T4563 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeySafeLeaderTest-1372617787587
[junit4:junit4] 2> 2553017 T4563 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 2553018 T4564 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 2553119 T4563 oasc.ZkTestServer.run start zk server on port:54529
[junit4:junit4] 2> 2553121 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2553135 T4570 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7de4782c name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2553136 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2553136 T4563 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 2553151 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2553157 T4572 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31fd8dd2 name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2553157 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2553158 T4563 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 2553165 T4563 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 2553171 T4563 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 2553177 T4563 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 2553183 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2553184 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2553199 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 2553200 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 2553209 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2553213 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2553221 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 2553222 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 2553228 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 2553229 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 2553237 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2553239 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2553246 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2553247 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2553253 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2553255 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2553262 T4563 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2553263 T4563 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2553716 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2553723 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54532
[junit4:junit4] 2> 2553724 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2553724 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2553725 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847
[junit4:junit4] 2> 2553726 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/solr.xml
[junit4:junit4] 2> 2553726 T4563 oasc.CoreContainer.<init> New CoreContainer 369478718
[junit4:junit4] 2> 2553727 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/'
[junit4:junit4] 2> 2553727 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/'
[junit4:junit4] 2> 2553843 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2553844 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2553844 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2553845 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2553845 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2553846 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2553846 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2553847 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2553848 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2553848 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2553884 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2553885 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2553885 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2553893 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2553897 T4583 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a74e7bb name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2553897 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2553901 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2553936 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2553943 T4585 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@753d02b2 name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2553944 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2553947 T4563 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 2553955 T4563 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 2553963 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 2553967 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54532_
[junit4:junit4] 2> 2553969 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54532_
[junit4:junit4] 2> 2553976 T4563 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 2553995 T4563 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 2554001 T4563 oasc.Overseer.start Overseer (id=89955879328219139-127.0.0.1:54532_-n_0000000000) starting
[junit4:junit4] 2> 2554011 T4563 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 2554030 T4587 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 2554034 T4563 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 2554039 T4563 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 2554044 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2554053 T4586 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 2554061 T4588 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2554062 T4588 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2555568 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2555569 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54532_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54532"}
[junit4:junit4] 2> 2555570 T4586 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2555570 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2555578 T4585 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> 2556073 T4588 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/collection1
[junit4:junit4] 2> 2556074 T4588 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 2556075 T4588 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2556075 T4588 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 2556079 T4588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/collection1/'
[junit4:junit4] 2> 2556080 T4588 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2556081 T4588 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/collection1/lib/README' to classloader
[junit4:junit4] 2> 2556146 T4588 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2556207 T4588 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2556210 T4588 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2556214 T4588 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2556842 T4588 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2556842 T4588 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2556843 T4588 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2556862 T4588 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2556869 T4588 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2556900 T4588 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2556921 T4588 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2556936 T4588 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2556940 T4588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2556940 T4588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2556941 T4588 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2556944 T4588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2556945 T4588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2556945 T4588 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2556946 T4588 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-controljetty-1372617787847/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/control/data/
[junit4:junit4] 2> 2556946 T4588 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2556947 T4588 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2556949 T4588 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/control/data
[junit4:junit4] 2> 2556950 T4588 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/control/data/index/
[junit4:junit4] 2> 2556951 T4588 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2556952 T4588 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/control/data/index
[junit4:junit4] 2> 2556962 T4588 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2556963 T4588 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2556967 T4588 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2556968 T4588 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2556969 T4588 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2556971 T4588 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2556972 T4588 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2556972 T4588 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2556977 T4588 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2556977 T4588 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2556978 T4588 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2556992 T4588 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2557014 T4588 oass.SolrIndexSearcher.<init> Opening Searcher@71b5ca49 main
[junit4:junit4] 2> 2557017 T4588 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2557018 T4588 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2557030 T4589 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71b5ca49 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2557041 T4588 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2557041 T4588 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54532 collection:control_collection shard:shard1
[junit4:junit4] 2> 2557044 T4588 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2557062 T4588 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2557075 T4588 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2557075 T4588 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2557076 T4588 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54532/collection1/
[junit4:junit4] 2> 2557076 T4588 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2557076 T4588 oasc.SyncStrategy.syncToMe http://127.0.0.1:54532/collection1/ has no replicas
[junit4:junit4] 2> 2557077 T4588 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54532/collection1/
[junit4:junit4] 2> 2557077 T4588 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2557091 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2557107 T4585 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> 2558625 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2558641 T4585 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> 2558677 T4588 oasc.ZkController.register We are http://127.0.0.1:54532/collection1/ and leader is http://127.0.0.1:54532/collection1/
[junit4:junit4] 2> 2558678 T4588 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54532
[junit4:junit4] 2> 2558679 T4588 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2558679 T4588 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2558680 T4588 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2558687 T4588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2558691 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2558691 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2558692 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2558728 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2558731 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2558737 T4592 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7940851e name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2558738 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2558741 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2558746 T4563 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 2559354 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2559376 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54536
[junit4:junit4] 2> 2559377 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2559378 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2559379 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318
[junit4:junit4] 2> 2559379 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/solr.xml
[junit4:junit4] 2> 2559380 T4563 oasc.CoreContainer.<init> New CoreContainer 1143676706
[junit4:junit4] 2> 2559380 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/'
[junit4:junit4] 2> 2559380 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/'
[junit4:junit4] 2> 2559551 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2559553 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2559554 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2559555 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2559556 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2559557 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2559558 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2559558 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2559559 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2559567 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2559619 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2559621 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2559622 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2559626 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2559635 T4603 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21097e62 name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2559638 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2559648 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2559696 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2559708 T4605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cf455b6 name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2559708 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2559721 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2560154 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2560156 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54532_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54532"}
[junit4:junit4] 2> 2560167 T4592 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> 2560168 T4585 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> 2560167 T4605 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> 2560731 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54536_
[junit4:junit4] 2> 2560734 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54536_
[junit4:junit4] 2> 2560741 T4585 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 2560745 T4605 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2560746 T4605 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> 2560753 T4585 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2560755 T4592 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2560756 T4592 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> 2560777 T4606 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2560777 T4606 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2561687 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2561689 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54536_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54536"}
[junit4:junit4] 2> 2561689 T4586 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 3
[junit4:junit4] 2> 2561689 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2561699 T4605 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> 2561700 T4585 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> 2561711 T4592 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> 2561788 T4606 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/collection1
[junit4:junit4] 2> 2561788 T4606 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2561791 T4606 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2561791 T4606 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2561796 T4606 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/collection1/'
[junit4:junit4] 2> 2561804 T4606 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2561805 T4606 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/collection1/lib/README' to classloader
[junit4:junit4] 2> 2561895 T4606 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2561980 T4606 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2561984 T4606 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2561993 T4606 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2562808 T4606 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2562809 T4606 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2562810 T4606 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2562830 T4606 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2562836 T4606 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2562870 T4606 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2562881 T4606 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2562891 T4606 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2562894 T4606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2562894 T4606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2562894 T4606 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2562897 T4606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2562897 T4606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2562897 T4606 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2562898 T4606 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty1-1372617793318/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1/
[junit4:junit4] 2> 2562898 T4606 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2562899 T4606 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2562901 T4606 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1
[junit4:junit4] 2> 2562901 T4606 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1/index/
[junit4:junit4] 2> 2562902 T4606 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2562903 T4606 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1/index
[junit4:junit4] 2> 2562909 T4606 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2562909 T4606 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2562918 T4606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2562919 T4606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2562920 T4606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2562921 T4606 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2562922 T4606 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2562922 T4606 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2562923 T4606 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2562924 T4606 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2562924 T4606 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2562936 T4606 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2562945 T4606 oass.SolrIndexSearcher.<init> Opening Searcher@5b9a2acc main
[junit4:junit4] 2> 2562947 T4606 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2562947 T4606 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2562954 T4607 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5b9a2acc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2562958 T4606 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2562958 T4606 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54536 collection:collection1 shard:shard1
[junit4:junit4] 2> 2562960 T4606 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 2562979 T4606 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2562985 T4606 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2562986 T4606 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2562986 T4606 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54536/collection1/
[junit4:junit4] 2> 2562986 T4606 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2562987 T4606 oasc.SyncStrategy.syncToMe http://127.0.0.1:54536/collection1/ has no replicas
[junit4:junit4] 2> 2562987 T4606 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54536/collection1/
[junit4:junit4] 2> 2562988 T4606 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 2563219 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2563235 T4605 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> 2563235 T4592 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> 2563235 T4585 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> 2563267 T4606 oasc.ZkController.register We are http://127.0.0.1:54536/collection1/ and leader is http://127.0.0.1:54536/collection1/
[junit4:junit4] 2> 2563267 T4606 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54536
[junit4:junit4] 2> 2563268 T4606 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2563268 T4606 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2563269 T4606 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2563281 T4606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2563292 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2563294 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2563295 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2563803 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2563808 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54539
[junit4:junit4] 2> 2563808 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2563809 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2563810 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918
[junit4:junit4] 2> 2563810 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/solr.xml
[junit4:junit4] 2> 2563811 T4563 oasc.CoreContainer.<init> New CoreContainer 1446382306
[junit4:junit4] 2> 2563811 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/'
[junit4:junit4] 2> 2563812 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/'
[junit4:junit4] 2> 2563925 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2563926 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2563927 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2563927 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2563928 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2563929 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2563929 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2563930 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2563930 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2563931 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2563964 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2563965 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2563966 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2563969 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2563979 T4619 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b9a7e2b name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2563980 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2563984 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2564024 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2564029 T4621 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1dc9843c name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2564030 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2564040 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2564753 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2564755 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54536_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54536"}
[junit4:junit4] 2> 2564766 T4605 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> 2564767 T4592 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> 2564767 T4585 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> 2564768 T4621 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> 2565048 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54539_
[junit4:junit4] 2> 2565057 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54539_
[junit4:junit4] 2> 2565062 T4585 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> 2565063 T4621 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2565064 T4605 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2565064 T4605 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> 2565064 T4621 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> 2565065 T4592 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2565066 T4592 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> 2565073 T4585 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2565082 T4622 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2565082 T4622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2566287 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2566289 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54539_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54539"}
[junit4:junit4] 2> 2566289 T4586 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 2566290 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2566297 T4592 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> 2566303 T4585 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> 2566306 T4605 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> 2566309 T4621 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> 2567087 T4622 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/collection1
[junit4:junit4] 2> 2567088 T4622 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2567090 T4622 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2567091 T4622 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2567094 T4622 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/collection1/'
[junit4:junit4] 2> 2567096 T4622 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2567097 T4622 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/collection1/lib/README' to classloader
[junit4:junit4] 2> 2567165 T4622 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2567229 T4622 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2567233 T4622 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2567241 T4622 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2567891 T4622 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2567892 T4622 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2567893 T4622 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2567904 T4622 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2567907 T4622 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2567946 T4622 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2567954 T4622 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2567961 T4622 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2567964 T4622 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2567964 T4622 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2567965 T4622 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2567968 T4622 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2567968 T4622 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2567969 T4622 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2567969 T4622 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty2-1372617797918/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2/
[junit4:junit4] 2> 2567969 T4622 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2567971 T4622 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2567972 T4622 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2
[junit4:junit4] 2> 2567973 T4622 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2/index/
[junit4:junit4] 2> 2567973 T4622 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2567974 T4622 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2/index
[junit4:junit4] 2> 2567980 T4622 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2567981 T4622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2567985 T4622 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2567986 T4622 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2567987 T4622 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2567992 T4622 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2567995 T4622 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2567995 T4622 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2567996 T4622 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2567997 T4622 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2567998 T4622 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2568010 T4622 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2568020 T4622 oass.SolrIndexSearcher.<init> Opening Searcher@6bda44f5 main
[junit4:junit4] 2> 2568022 T4622 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2568022 T4622 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2568032 T4623 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6bda44f5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2568038 T4622 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2568038 T4622 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54539 collection:collection1 shard:shard2
[junit4:junit4] 2> 2568040 T4622 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 2568067 T4622 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2568076 T4622 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2568077 T4622 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2568077 T4622 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54539/collection1/
[junit4:junit4] 2> 2568077 T4622 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2568078 T4622 oasc.SyncStrategy.syncToMe http://127.0.0.1:54539/collection1/ has no replicas
[junit4:junit4] 2> 2568078 T4622 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54539/collection1/
[junit4:junit4] 2> 2568078 T4622 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2569312 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2569336 T4585 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> 2569336 T4592 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> 2569336 T4605 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> 2569337 T4621 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> 2569382 T4622 oasc.ZkController.register We are http://127.0.0.1:54539/collection1/ and leader is http://127.0.0.1:54539/collection1/
[junit4:junit4] 2> 2569383 T4622 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54539
[junit4:junit4] 2> 2569383 T4622 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2569383 T4622 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2569384 T4622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2569398 T4622 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2569401 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2569402 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2569403 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2569963 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2569969 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54542
[junit4:junit4] 2> 2569970 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2569971 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2569971 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009
[junit4:junit4] 2> 2569972 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/solr.xml
[junit4:junit4] 2> 2569973 T4563 oasc.CoreContainer.<init> New CoreContainer 1580054026
[junit4:junit4] 2> 2569974 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/'
[junit4:junit4] 2> 2569974 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/'
[junit4:junit4] 2> 2570095 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2570096 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2570097 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2570097 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2570097 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2570098 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2570098 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2570099 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2570099 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2570100 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2570132 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2570133 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2570134 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2570137 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2570141 T4635 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5d05f9f5 name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2570142 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2570145 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2570180 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2570185 T4637 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@270715fb name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2570186 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2570195 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2570858 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2570860 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54539_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54539"}
[junit4:junit4] 2> 2570870 T4637 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> 2570871 T4621 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> 2570871 T4585 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> 2570876 T4605 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> 2570878 T4592 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> 2571203 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54542_
[junit4:junit4] 2> 2571206 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54542_
[junit4:junit4] 2> 2571211 T4585 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> 2571215 T4621 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2571216 T4621 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> 2571216 T4637 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2571217 T4637 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> 2571217 T4605 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2571217 T4605 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> 2571218 T4592 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2571218 T4592 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> 2571231 T4585 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2571242 T4638 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2571243 T4638 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2572387 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2572389 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54542_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54542"}
[junit4:junit4] 2> 2572389 T4586 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 2572389 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 2572398 T4605 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> 2572406 T4621 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> 2572409 T4585 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> 2572411 T4637 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> 2572417 T4592 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> 2573249 T4638 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/collection1
[junit4:junit4] 2> 2573250 T4638 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2573251 T4638 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2573252 T4638 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2573256 T4638 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/collection1/'
[junit4:junit4] 2> 2573258 T4638 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2573259 T4638 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/collection1/lib/README' to classloader
[junit4:junit4] 2> 2573304 T4638 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2573353 T4638 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2573356 T4638 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2573368 T4638 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2573969 T4638 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2573970 T4638 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2573971 T4638 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2573983 T4638 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2573987 T4638 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2574014 T4638 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2574021 T4638 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2574027 T4638 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2574031 T4638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2574033 T4638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2574036 T4638 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2574039 T4638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2574040 T4638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2574040 T4638 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2574040 T4638 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty3-1372617804009/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3/
[junit4:junit4] 2> 2574041 T4638 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2574042 T4638 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2574043 T4638 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3
[junit4:junit4] 2> 2574044 T4638 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3/index/
[junit4:junit4] 2> 2574044 T4638 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2574045 T4638 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3/index
[junit4:junit4] 2> 2574053 T4638 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2574054 T4638 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2574061 T4638 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2574062 T4638 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2574062 T4638 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2574064 T4638 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2574064 T4638 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2574065 T4638 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2574065 T4638 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2574066 T4638 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2574067 T4638 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2574077 T4638 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2574085 T4638 oass.SolrIndexSearcher.<init> Opening Searcher@9d904d8 main
[junit4:junit4] 2> 2574087 T4638 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2574087 T4638 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2574099 T4639 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9d904d8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2574103 T4638 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2574104 T4638 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54542 collection:collection1 shard:shard3
[junit4:junit4] 2> 2574105 T4638 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4:junit4] 2> 2574122 T4638 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2574128 T4638 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2574129 T4638 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2574129 T4638 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54542/collection1/
[junit4:junit4] 2> 2574129 T4638 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2574130 T4638 oasc.SyncStrategy.syncToMe http://127.0.0.1:54542/collection1/ has no replicas
[junit4:junit4] 2> 2574130 T4638 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54542/collection1/
[junit4:junit4] 2> 2574130 T4638 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4:junit4] 2> 2575418 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2575435 T4637 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> 2575435 T4592 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> 2575436 T4605 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> 2575436 T4585 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> 2575436 T4621 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> 2575487 T4638 oasc.ZkController.register We are http://127.0.0.1:54542/collection1/ and leader is http://127.0.0.1:54542/collection1/
[junit4:junit4] 2> 2575488 T4638 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54542
[junit4:junit4] 2> 2575488 T4638 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2575489 T4638 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2575489 T4638 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2575494 T4638 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2575497 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2575498 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2575500 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2576035 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2576042 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54545
[junit4:junit4] 2> 2576043 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2576044 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2576045 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123
[junit4:junit4] 2> 2576045 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/solr.xml
[junit4:junit4] 2> 2576046 T4563 oasc.CoreContainer.<init> New CoreContainer 1841100875
[junit4:junit4] 2> 2576046 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/'
[junit4:junit4] 2> 2576047 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/'
[junit4:junit4] 2> 2576225 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2576226 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2576226 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2576227 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2576227 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2576228 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2576228 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2576229 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2576229 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2576230 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2576268 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2576269 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2576270 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2576272 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2576276 T4651 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23e19613 name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2576277 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2576281 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2576313 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2576317 T4653 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@41745712 name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2576317 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2576331 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2576954 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2576955 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54542_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54542"}
[junit4:junit4] 2> 2576964 T4585 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> 2576968 T4592 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> 2576969 T4621 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> 2576970 T4637 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> 2576970 T4605 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> 2576971 T4653 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> 2577341 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54545_
[junit4:junit4] 2> 2577344 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54545_
[junit4:junit4] 2> 2577350 T4585 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> 2577355 T4605 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2577356 T4605 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> 2577356 T4621 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2577356 T4621 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> 2577357 T4637 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2577357 T4637 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> 2577358 T4592 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2577358 T4592 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> 2577358 T4653 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2577358 T4653 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> 2577369 T4585 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2577378 T4654 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2577379 T4654 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2578483 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2578485 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54545_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54545"}
[junit4:junit4] 2> 2578485 T4586 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 2578485 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2578495 T4585 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> 2578495 T4621 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> 2578498 T4653 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> 2578499 T4637 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> 2578499 T4592 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> 2578500 T4605 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> 2579388 T4654 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/collection1
[junit4:junit4] 2> 2579392 T4654 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2579400 T4654 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2579401 T4654 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2579404 T4654 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/collection1/'
[junit4:junit4] 2> 2579405 T4654 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2579406 T4654 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/collection1/lib/README' to classloader
[junit4:junit4] 2> 2579472 T4654 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2579553 T4654 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2579556 T4654 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2579562 T4654 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2580281 T4654 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2580282 T4654 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2580283 T4654 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2580295 T4654 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2580300 T4654 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2580336 T4654 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2580343 T4654 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2580353 T4654 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2580356 T4654 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2580356 T4654 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2580357 T4654 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2580360 T4654 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2580360 T4654 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2580361 T4654 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2580361 T4654 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty4-1372617810123/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty4/
[junit4:junit4] 2> 2580361 T4654 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2580362 T4654 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2580363 T4654 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty4
[junit4:junit4] 2> 2580364 T4654 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty4/index/
[junit4:junit4] 2> 2580365 T4654 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2580366 T4654 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty4/index
[junit4:junit4] 2> 2580373 T4654 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2580374 T4654 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2580378 T4654 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2580379 T4654 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2580380 T4654 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2580381 T4654 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2580382 T4654 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2580382 T4654 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2580383 T4654 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2580392 T4654 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2580393 T4654 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2580402 T4654 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2580413 T4654 oass.SolrIndexSearcher.<init> Opening Searcher@38881ab9 main
[junit4:junit4] 2> 2580414 T4654 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2580415 T4654 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2580422 T4655 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38881ab9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2580427 T4654 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2580428 T4654 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54545 collection:collection1 shard:shard1
[junit4:junit4] 2> 2580434 T4654 oasc.ZkController.register We are http://127.0.0.1:54545/collection1/ and leader is http://127.0.0.1:54536/collection1/
[junit4:junit4] 2> 2580435 T4654 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54545
[junit4:junit4] 2> 2580435 T4654 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2580435 T4654 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C929 name=collection1 org.apache.solr.core.SolrCore@75cbbe9 url=http://127.0.0.1:54545/collection1 node=127.0.0.1:54545_ C929_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:54545_, base_url=http://127.0.0.1:54545}
[junit4:junit4] 2> 2580436 T4656 C929 P54545 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2580437 T4656 C929 P54545 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2580437 T4656 C929 P54545 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2580437 T4656 C929 P54545 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2580440 T4654 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2580440 T4656 C929 P54545 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2580464 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2580465 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2580465 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2580499 T4599 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2580955 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2580965 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54549
[junit4:junit4] 2> 2580967 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2580968 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2580969 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071
[junit4:junit4] 2> 2580969 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/solr.xml
[junit4:junit4] 2> 2580970 T4563 oasc.CoreContainer.<init> New CoreContainer 1055543616
[junit4:junit4] 2> 2580971 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/'
[junit4:junit4] 2> 2580972 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/'
[junit4:junit4] 2> 2581091 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2581092 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2581092 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2581093 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2581093 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2581094 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2581094 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2581095 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2581095 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2581096 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2581137 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2581138 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2581138 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2581140 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2581145 T4668 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@44c59420 name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2581145 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2581149 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2581177 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2581189 T4670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d8de61f name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2581190 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2581203 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2581523 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2581525 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54545_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54545"}
[junit4:junit4] 2> 2581539 T4621 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> 2581539 T4585 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> 2581540 T4653 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> 2581540 T4637 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> 2581540 T4670 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> 2581540 T4592 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> 2581540 T4605 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> 2582212 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54549_
[junit4:junit4] 2> 2582215 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54549_
[junit4:junit4] 2> 2582221 T4585 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> 2582227 T4585 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582229 T4670 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> 2582239 T4671 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2582239 T4671 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2582241 T4621 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582242 T4621 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> 2582246 T4670 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582248 T4592 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582251 T4592 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> 2582252 T4653 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582253 T4653 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> 2582246 T4605 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582254 T4605 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> 2582252 T4637 oascc.ZkStateReader$3.process Updating live nodes... (6)
[junit4:junit4] 2> 2582254 T4637 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> 2582502 T4599 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 2582503 T4599 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:54545_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2004
[junit4:junit4] 2> 2583055 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2583057 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54549_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54549"}
[junit4:junit4] 2> 2583057 T4586 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 2583057 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2583069 T4637 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> 2583070 T4653 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> 2583070 T4592 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> 2583071 T4585 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> 2583070 T4605 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> 2583070 T4621 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> 2583070 T4670 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> 2583242 T4671 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/collection1
[junit4:junit4] 2> 2583243 T4671 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2583244 T4671 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2583244 T4671 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2583251 T4671 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/collection1/'
[junit4:junit4] 2> 2583254 T4671 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2583254 T4671 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/collection1/lib/README' to classloader
[junit4:junit4] 2> 2583308 T4671 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2583362 T4671 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2583366 T4671 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2583371 T4671 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2583933 T4671 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2583934 T4671 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2583934 T4671 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2583953 T4671 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2583959 T4671 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2584009 T4671 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2584017 T4671 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2584027 T4671 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2584030 T4671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2584031 T4671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2584032 T4671 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2584034 T4671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2584035 T4671 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2584036 T4671 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2584036 T4671 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty5-1372617815071/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty5/
[junit4:junit4] 2> 2584037 T4671 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2584038 T4671 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2584041 T4671 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty5
[junit4:junit4] 2> 2584042 T4671 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty5/index/
[junit4:junit4] 2> 2584048 T4671 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty5/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2584054 T4671 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty5/index
[junit4:junit4] 2> 2584063 T4671 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty5/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2584064 T4671 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2584070 T4671 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2584070 T4671 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2584071 T4671 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2584072 T4671 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2584073 T4671 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2584074 T4671 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2584074 T4671 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2584076 T4671 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2584077 T4671 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2584086 T4671 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2584104 T4671 oass.SolrIndexSearcher.<init> Opening Searcher@18c8c3c6 main
[junit4:junit4] 2> 2584106 T4671 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2584106 T4671 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2584116 T4672 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18c8c3c6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2584122 T4671 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2584123 T4671 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54549 collection:collection1 shard:shard2
[junit4:junit4] 2> 2584131 T4671 oasc.ZkController.register We are http://127.0.0.1:54549/collection1/ and leader is http://127.0.0.1:54539/collection1/
[junit4:junit4] 2> 2584132 T4671 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54549
[junit4:junit4] 2> 2584132 T4671 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2584132 T4671 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C930 name=collection1 org.apache.solr.core.SolrCore@312c21b9 url=http://127.0.0.1:54549/collection1 node=127.0.0.1:54549_ C930_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:54549_, base_url=http://127.0.0.1:54549}
[junit4:junit4] 2> 2584133 T4673 C930 P54549 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2584134 T4673 C930 P54549 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2584134 T4673 C930 P54549 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2584134 T4673 C930 P54549 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2584136 T4671 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2584137 T4673 C930 P54549 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2584180 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2584181 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2584182 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2584206 T4617 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C931 name=collection1 org.apache.solr.core.SolrCore@75cbbe9 url=http://127.0.0.1:54545/collection1 node=127.0.0.1:54545_ C931_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:54545_, base_url=http://127.0.0.1:54545}
[junit4:junit4] 2> 2584505 T4656 C931 P54545 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54536/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2584508 T4656 C931 P54545 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54545 START replicas=[http://127.0.0.1:54536/collection1/] nUpdates=100
[junit4:junit4] 2> 2584509 T4656 C931 P54545 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2584510 T4656 C931 P54545 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2584511 T4656 C931 P54545 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2584514 T4656 C931 P54545 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2584514 T4656 C931 P54545 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2584514 T4656 C931 P54545 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54536/collection1/. core=collection1
[junit4:junit4] 2> 2584515 T4656 C931 P54545 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C932 name=collection1 org.apache.solr.core.SolrCore@657d7ef8 url=http://127.0.0.1:54536/collection1 node=127.0.0.1:54536_ C932_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54536_, base_url=http://127.0.0.1:54536, leader=true}
[junit4:junit4] 2> 2584540 T4600 C932 P54536 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> 2584581 T4601 C932 P54536 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2584592 T4601 C932 P54536 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2584598 T4601 C932 P54536 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2584600 T4601 C932 P54536 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 2584601 T4601 C932 P54536 oass.SolrIndexSearcher.<init> Opening Searcher@323618a1 realtime
[junit4:junit4] 2> 2584601 T4601 C932 P54536 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2584602 T4601 C932 P54536 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 21
[junit4:junit4] 2> 2584609 T4656 C931 P54545 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2584610 T4656 C931 P54545 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2584614 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2584620 T4597 C932 P54536 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2584622 T4597 C932 P54536 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=5
[junit4:junit4] 2> 2584622 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54549_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54549"}
[junit4:junit4] 2> 2584624 T4656 C931 P54545 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2584624 T4656 C931 P54545 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2584624 T4656 C931 P54545 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2584625 T4656 C931 P54545 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2584631 T4656 C931 P54545 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2584645 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54545_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54545"}
[junit4:junit4] 2> 2584664 T4621 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> 2584664 T4670 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> 2584665 T4653 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> 2584665 T4637 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> 2584666 T4605 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> 2584666 T4585 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> 2584666 T4592 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> 2585003 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2585014 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54556
[junit4:junit4] 2> 2585015 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2585015 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2585016 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801
[junit4:junit4] 2> 2585017 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/solr.xml
[junit4:junit4] 2> 2585018 T4563 oasc.CoreContainer.<init> New CoreContainer 1024768199
[junit4:junit4] 2> 2585018 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/'
[junit4:junit4] 2> 2585020 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/'
[junit4:junit4] 2> 2585202 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2585203 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2585204 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2585204 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2585205 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2585205 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2585206 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2585207 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2585207 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2585207 T4617 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 6, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2585209 T4617 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=6&state=recovering&nodeName=127.0.0.1:54549_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 2585208 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2585264 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2585265 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2585266 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2585269 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2585275 T4686 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@171e8560 name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2585276 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2585281 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2585319 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2585327 T4688 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@218a9545 name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2585328 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2585344 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2586356 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54556_
[junit4:junit4] 2> 2586358 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54556_
[junit4:junit4] 2> 2586364 T4585 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> 2586369 T4585 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586374 T4670 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> 2586381 T4621 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586381 T4621 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> 2586382 T4637 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586382 T4637 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> 2586382 T4653 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586383 T4653 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> 2586383 T4605 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586383 T4605 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> 2586384 T4592 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586384 T4592 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> 2586391 T4688 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> 2586402 T4689 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2586402 T4689 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2586403 T4670 oascc.ZkStateReader$3.process Updating live nodes... (7)
[junit4:junit4] 2> ASYNC NEW_CORE C933 name=collection1 org.apache.solr.core.SolrCore@312c21b9 url=http://127.0.0.1:54549/collection1 node=127.0.0.1:54549_ C933_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:54549_, base_url=http://127.0.0.1:54549}
[junit4:junit4] 2> 2587223 T4673 C933 P54549 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54539/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2587223 T4673 C933 P54549 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54549 START replicas=[http://127.0.0.1:54539/collection1/] nUpdates=100
[junit4:junit4] 2> 2587224 T4673 C933 P54549 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2587224 T4673 C933 P54549 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2587225 T4673 C933 P54549 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2587225 T4673 C933 P54549 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2587225 T4673 C933 P54549 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2587225 T4673 C933 P54549 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54539/collection1/. core=collection1
[junit4:junit4] 2> 2587226 T4673 C933 P54549 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C934 name=collection1 org.apache.solr.core.SolrCore@73ff5ad url=http://127.0.0.1:54539/collection1 node=127.0.0.1:54539_ C934_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54539_, base_url=http://127.0.0.1:54539, leader=true}
[junit4:junit4] 2> 2587264 T4617 C934 P54539 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> 2587269 T4617 C934 P54539 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2587275 T4617 C934 P54539 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2587276 T4617 C934 P54539 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2587276 T4617 C934 P54539 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 2587277 T4617 C934 P54539 oass.SolrIndexSearcher.<init> Opening Searcher@5b9206a1 realtime
[junit4:junit4] 2> 2587278 T4617 C934 P54539 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2587278 T4617 C934 P54539 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 9
[junit4:junit4] 2> 2587280 T4673 C933 P54549 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2587281 T4673 C933 P54549 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2587286 T4612 C934 P54539 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2587287 T4612 C934 P54539 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 2587288 T4673 C933 P54549 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2587288 T4673 C933 P54549 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2587289 T4673 C933 P54549 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2587289 T4673 C933 P54549 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2587291 T4673 C933 P54549 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2587703 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2587705 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54556_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54556"}
[junit4:junit4] 2> 2587705 T4586 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 2587706 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard3
[junit4:junit4] 2> 2587713 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"6",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54549_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54549"}
[junit4:junit4] 2> 2587726 T4621 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> 2587730 T4653 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> 2587730 T4585 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> 2587730 T4688 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> 2587731 T4592 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> 2587730 T4637 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> 2587733 T4670 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> 2587735 T4605 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> 2588407 T4689 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/collection1
[junit4:junit4] 2> 2588407 T4689 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2588409 T4689 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2588409 T4689 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2588412 T4689 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/collection1/'
[junit4:junit4] 2> 2588414 T4689 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2588414 T4689 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/collection1/lib/README' to classloader
[junit4:junit4] 2> 2588474 T4689 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2588527 T4689 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2588530 T4689 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2588539 T4689 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2589112 T4689 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2589113 T4689 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2589114 T4689 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2589130 T4689 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2589134 T4689 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2589167 T4689 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2589175 T4689 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2589182 T4689 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2589188 T4689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2589188 T4689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2589188 T4689 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2589193 T4689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2589194 T4689 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2589194 T4689 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2589194 T4689 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty6-1372617818801/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty6/
[junit4:junit4] 2> 2589195 T4689 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2589195 T4689 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2589197 T4689 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty6
[junit4:junit4] 2> 2589197 T4689 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty6/index/
[junit4:junit4] 2> 2589198 T4689 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty6/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2589199 T4689 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty6/index
[junit4:junit4] 2> 2589205 T4689 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty6/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2589206 T4689 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2589210 T4689 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2589210 T4689 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2589211 T4689 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2589213 T4689 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2589214 T4689 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2589214 T4689 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2589218 T4689 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2589219 T4689 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2589220 T4689 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2589230 T4689 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2589248 T4689 oass.SolrIndexSearcher.<init> Opening Searcher@5ebedd24 main
[junit4:junit4] 2> 2589249 T4689 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2589249 T4689 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2589261 T4691 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5ebedd24 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2589270 T4689 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2589273 T4689 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54556 collection:collection1 shard:shard3
[junit4:junit4] 2> 2589280 T4689 oasc.ZkController.register We are http://127.0.0.1:54556/collection1/ and leader is http://127.0.0.1:54542/collection1/
[junit4:junit4] 2> 2589280 T4689 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54556
[junit4:junit4] 2> 2589280 T4689 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2589281 T4689 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C935 name=collection1 org.apache.solr.core.SolrCore@3f4d3398 url=http://127.0.0.1:54556/collection1 node=127.0.0.1:54556_ C935_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:54556_, base_url=http://127.0.0.1:54556}
[junit4:junit4] 2> 2589282 T4692 C935 P54556 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2589282 T4689 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2589282 T4692 C935 P54556 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2589283 T4692 C935 P54556 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2589284 T4692 C935 P54556 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2589286 T4692 C935 P54556 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2589339 T4628 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2589339 T4563 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 2589340 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2589341 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2589820 T4563 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2589826 T4563 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54563
[junit4:junit4] 2> 2589827 T4563 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2589828 T4563 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2589829 T4563 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939
[junit4:junit4] 2> 2589830 T4563 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/solr.xml
[junit4:junit4] 2> 2589831 T4563 oasc.CoreContainer.<init> New CoreContainer 360134940
[junit4:junit4] 2> 2589832 T4563 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/'
[junit4:junit4] 2> 2589833 T4563 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/'
[junit4:junit4] 2> 2589952 T4563 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2589953 T4563 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2589954 T4563 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2589954 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2589955 T4563 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2589955 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2589956 T4563 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2589956 T4563 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2589957 T4563 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2589958 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2589994 T4563 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2590000 T4563 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54529/solr
[junit4:junit4] 2> 2590001 T4563 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2590004 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2590009 T4704 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3867efb5 name:ZooKeeperConnection Watcher:127.0.0.1:54529 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2590010 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2590014 T4563 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2590048 T4563 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2590056 T4706 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7fc0f5fd name:ZooKeeperConnection Watcher:127.0.0.1:54529/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2590062 T4563 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2590074 T4563 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2590759 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2590761 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54556_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54556"}
[junit4:junit4] 2> 2590777 T4637 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> 2590779 T4592 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> 2590781 T4688 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> 2590783 T4585 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> 2590784 T4706 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> 2590786 T4621 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> 2590788 T4670 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> 2590790 T4653 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> 2590792 T4605 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> 2591084 T4563 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54563_
[junit4:junit4] 2> 2591086 T4563 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54563_
[junit4:junit4] 2> 2591093 T4585 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> 2591093 T4688 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> 2591093 T4670 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> 2591099 T4621 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591099 T4621 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> 2591099 T4706 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591100 T4706 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> 2591100 T4592 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591100 T4592 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> 2591101 T4637 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591101 T4637 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> 2591101 T4653 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591101 T4653 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> 2591102 T4605 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591102 T4605 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> 2591115 T4585 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591117 T4670 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591117 T4688 oascc.ZkStateReader$3.process Updating live nodes... (8)
[junit4:junit4] 2> 2591125 T4707 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2591125 T4707 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2591353 T4628 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 7, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 2591354 T4628 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=7&state=recovering&nodeName=127.0.0.1:54556_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2016
[junit4:junit4] 2> 2592285 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2592287 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"8",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54563_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54563"}
[junit4:junit4] 2> 2592287 T4586 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4:junit4] 2> 2592287 T4586 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2592299 T4706 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> 2592299 T4621 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> 2592300 T4670 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> 2592300 T4653 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> 2592300 T4637 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> 2592301 T4605 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> 2592301 T4585 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> 2592302 T4688 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> 2592305 T4592 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> 2593130 T4707 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/collection1
[junit4:junit4] 2> 2593132 T4707 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2593136 T4707 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2593137 T4707 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2593140 T4707 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/collection1/'
[junit4:junit4] 2> 2593141 T4707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2593142 T4707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/collection1/lib/README' to classloader
[junit4:junit4] 2> 2593204 T4707 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2593251 T4707 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2593254 T4707 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2593276 T4707 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C936 name=collection1 org.apache.solr.core.SolrCore@3f4d3398 url=http://127.0.0.1:54556/collection1 node=127.0.0.1:54556_ C936_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:54556_, base_url=http://127.0.0.1:54556}
[junit4:junit4] 2> 2593356 T4692 C936 P54556 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54542/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2593357 T4692 C936 P54556 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54556 START replicas=[http://127.0.0.1:54542/collection1/] nUpdates=100
[junit4:junit4] 2> 2593361 T4692 C936 P54556 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2593361 T4692 C936 P54556 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2593362 T4692 C936 P54556 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2593399 T4692 C936 P54556 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2593399 T4692 C936 P54556 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2593400 T4692 C936 P54556 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54542/collection1/. core=collection1
[junit4:junit4] 2> 2593400 T4692 C936 P54556 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C937 name=collection1 org.apache.solr.core.SolrCore@4d8afb22 url=http://127.0.0.1:54542/collection1 node=127.0.0.1:54542_ C937_STATE=coll:collection1 core:collection1 props:{shard=shard3, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54542_, base_url=http://127.0.0.1:54542, leader=true}
[junit4:junit4] 2> 2593414 T4633 C937 P54542 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> 2593445 T4629 C937 P54542 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2593453 T4629 C937 P54542 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2593454 T4629 C937 P54542 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2593455 T4629 C937 P54542 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 2593456 T4629 C937 P54542 oass.SolrIndexSearcher.<init> Opening Searcher@96e85f8 realtime
[junit4:junit4] 2> 2593456 T4629 C937 P54542 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2593456 T4629 C937 P54542 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 11
[junit4:junit4] 2> 2593458 T4692 C936 P54556 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2593459 T4692 C936 P54556 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2593478 T4631 C937 P54542 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2593479 T4631 C937 P54542 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 2593480 T4692 C936 P54556 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2593481 T4692 C936 P54556 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2593481 T4692 C936 P54556 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2593481 T4692 C936 P54556 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2593485 T4692 C936 P54556 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2593825 T4586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2593827 T4586 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"7",
[junit4:junit4] 2> "numShards":"3",
[junit4:junit4] 2> "shard":"shard3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"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:54556_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54556"}
[junit4:junit4] 2> 2593836 T4688 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> 2593836 T4621 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> 2593837 T4592 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> 2593836 T4706 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> 2593837 T4585 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> 2593836 T4605 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> 2593836 T4653 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> 2593836 T4637 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> 2593836 T4670 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> 2593916 T4707 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2593916 T4707 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 2593917 T4707 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2593935 T4707 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2593939 T4707 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2593966 T4707 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2593973 T4707 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2593980 T4707 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2593983 T4707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2593983 T4707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2593983 T4707 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2593985 T4707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2593986 T4707 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 2593987 T4707 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2593987 T4707 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-jetty7-1372617823939/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty7/
[junit4:junit4] 2> 2593988 T4707 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5aaefcbb
[junit4:junit4] 2> 2593988 T4707 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 2593989 T4707 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty7
[junit4:junit4] 2> 2593990 T4707 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty7/index/
[junit4:junit4] 2> 2593991 T4707 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty7/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2593994 T4707 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty7/index
[junit4:junit4] 2> 2594005 T4707 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1372617787587/jetty7/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 2594006 T4707 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2594010 T4707 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2594010 T4707 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2594011 T4707 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2594012 T4707 oasc.RequestHandlers.initHandlersFr
[...truncated too long message...]
tCnxn.java:1157)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1097)
[junit4:junit4] 2> 62) Thread[id=4625, name=HashSessionScavenger-138, state=TIMED_WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> at java.lang.Object.wait(Native Method)
[junit4:junit4] 2> at java.util.TimerThread.mainLoop(Timer.java:509)
[junit4:junit4] 2> at java.util.TimerThread.run(Timer.java:462)
[junit4:junit4] 2> 63) Thread[id=4732, name=qtp322255375-4732 Acceptor0 SelectChannelConnector@127.0.0.1:54575, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:956)
[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:680)
[junit4:junit4] 2> 64) Thread[id=4730, name=HashSessionScavenger-144, state=TIMED_WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> at java.lang.Object.wait(Native Method)
[junit4:junit4] 2> at java.util.TimerThread.mainLoop(Timer.java:509)
[junit4:junit4] 2> at java.util.TimerThread.run(Timer.java:462)
[junit4:junit4] 2> 65) Thread[id=4609, name=HashSessionScavenger-137, state=TIMED_WAITING, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> at java.lang.Object.wait(Native Method)
[junit4:junit4] 2> at java.util.TimerThread.mainLoop(Timer.java:509)
[junit4:junit4] 2> at java.util.TimerThread.run(Timer.java:462)
[junit4:junit4] 2> 66) Thread[id=4785, name=qtp204122503-4785 Selector0, state=RUNNABLE, group=TGRP-ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> at sun.nio.ch.IOUtil.drain(Native Method)
[junit4:junit4] 2> at sun.nio.ch.KQueueSelectorImpl.updateSelectedKeys(KQueueSelectorImpl.java:117)
[junit4:junit4] 2> at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:74)
[junit4:junit4] 2> at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
[junit4:junit4] 2> at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
[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:680)
[junit4:junit4] 2> 67) Thread[id=4799, name=searcherExecutor-3242-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:156)
[junit4:junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
[junit4:junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:957)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:917)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:680)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=Pulsing41(freqCutoff=8 minBlockSize=76 maxBlockSize=237), text=MockFixedIntBlock(blockSize=1946), _version_=Pulsing41(freqCutoff=8 minBlockSize=76 maxBlockSize=237), rnd_b=PostingsFormat(name=MockSep), intDefault=Pulsing41(freqCutoff=8 minBlockSize=76 maxBlockSize=237), id=PostingsFormat(name=MockSep), timestamp=Pulsing41(freqCutoff=8 minBlockSize=76 maxBlockSize=237), a_t=Pulsing41(freqCutoff=8 minBlockSize=76 maxBlockSize=237), range_facet_sl=MockFixedIntBlock(blockSize=1946), range_facet_si=PostingsFormat(name=Asserting), other_tl1=Pulsing41(freqCutoff=8 minBlockSize=76 maxBlockSize=237), multiDefault=PostingsFormat(name=Asserting), a_si=PostingsFormat(name=Asserting)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=sl, timezone=Pacific/Noumea
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Apple Inc. 1.6.0_51 (64-bit)/cpus=2,threads=81,free=40528592,total=281214976
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestAnalyzedSuggestions, TestFoldingMultitermQuery, TestConfig, TestCloudManagedSchemaAddField, OutputWriterTest, TestStressVersions, CollectionsAPIDistributedZkTest, SolrCoreTest, SearchHandlerTest, ExternalFileFieldSortTest, ZkCLITest, TestFunctionQuery, SortByFunctionTest, TestLMDirichletSimilarityFactory, TestPluginEnable, TestFieldTypeCollectionResource, TestCopyFieldCollectionResource, RegexBoostProcessorTest, LeaderElectionTest, BadIndexSchemaTest, ChaosMonkeyNothingIsSafeTest, ResourceLoaderTest, TestFieldResource, DistributedQueryElevationComponentTest, TestDefaultSimilarityFactory, TestExtendedDismaxParser, AlternateDirectoryTest, TestLMJelinekMercerSimilarityFactory, TestRangeQuery, FileBasedSpellCheckerTest, SignatureUpdateProcessorFactoryTest, TestSolr4Spatial, TestStressRecovery, UpdateParamsTest, TestCoreDiscovery, TestFieldTypeResource, RAMDirectoryFactoryTest, ConvertedLegacyTest, OverseerTest, BasicDistributedZkTest, LukeRequestHandlerTest, CSVRequestHandlerTest, ZkSolrClientTest, QueryParsingTest, SolrIndexSplitterTest, TestLFUCache, TestSolrIndexConfig, TestSweetSpotSimilarityFactory, TestGroupingSearch, OpenExchangeRatesOrgProviderTest, TestRTGBase, ReturnFieldsTest, TestDistributedSearch, DisMaxRequestHandlerTest, SpatialFilterTest, TestXIncludeConfig, TestUpdate, SpellPossibilityIteratorTest, TestStressLucene, SolrCoreCheckLockOnStartupTest, DocumentBuilderTest, TestSolrCoreProperties, TestPropInject, UUIDFieldTest, CacheHeaderTest, NotRequiredUniqueKeyTest, ShowFileRequestHandlerTest, DocValuesTest, TestHashPartitioner, SolrTestCaseJ4Test, IndexReaderFactoryTest, TestShardHandlerFactory, TestBinaryResponseWriter, FileUtilsTest, NoCacheHeaderTest, SuggesterTSTTest, TestDynamicFieldCollectionResource, TestSolrXmlPersistence, TestUtils, BasicZkTest, TestManagedSchemaFieldResource, DirectUpdateHandlerTest, PrimitiveFieldTypeTest, DistributedSpellCheckComponentTest, SchemaVersionSpecificBehaviorTest, IndexBasedSpellCheckerTest, TestDFRSimilarityFactory, CopyFieldTest, TestReloadAndDeleteDocs, TestDynamicFieldResource, PluginInfoTest, PreAnalyzedUpdateProcessorTest, SampleTest, DocValuesMultiTest, TestSurroundQueryParser, TestMultiCoreConfBootstrap, ClusterStateUpdateTest, PathHierarchyTokenizerFactoryTest, TestLazyCores, TestCoreContainer, HighlighterConfigTest, CurrencyFieldOpenExchangeTest, TestRandomFaceting, JsonLoaderTest, ResponseLogComponentTest, TestTrie, TestBinaryField, TermsComponentTest, TestNumberUtils, QueryEqualityTest, TermVectorComponentDistributedTest, TestRemoteStreaming, TestStressReorder, TestCSVResponseWriter, TestPseudoReturnFields, ShardSplitTest, TestLRUCache, TestBadConfig, FastVectorHighlighterTest, SynonymTokenizerTest, DirectSolrConnectionTest, CoreAdminHandlerTest, UpdateRequestProcessorFactoryTest, TestOmitPositions, TestCollationKeyRangeQueries, SolrPluginUtilsTest, TestComponentsName, SpellCheckComponentTest, SolrRequestParserTest, SoftAutoCommitTest, TestFuzzyAnalyzedSuggestions, TestReplicationHandler, FieldMutatingUpdateProcessorTest, ClusterStateTest, PingRequestHandlerTest, TestZkChroot, TestFastWriter, TestCloudManagedSchema, SOLR749Test, SliceStateUpdateTest, WordBreakSolrSpellCheckerTest, IndexSchemaTest, TestFiltering, PeerSyncTest, TestManagedSchema, TestQueryTypes, ChaosMonkeySafeLeaderTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.seed=E193A21E9B15C7E2 -Dtests.slow=true -Dtests.locale=sl -Dtests.timezone=Pacific/Noumea -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 0.00s | ChaosMonkeySafeLeaderTest (suite) <<<
[junit4:junit4] > Throwable #1: java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([E193A21E9B15C7E2]:0)
[junit4:junit4] Completed in 7233.44s, 1 test, 2 errors <<< FAILURES!
[...truncated 454 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:392: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:372: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1248: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:892: There were test failures: 299 suites, 1290 tests, 1 suite-level error, 1 error, 528 ignored (1 assumption)
Total time: 216 minutes 1 second
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0 -XX:+UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure