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/28 19:51:14 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 605 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/605/
Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseSerialGC
2 tests failed.
REGRESSION: org.apache.solr.cloud.AliasIntegrationTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:49224 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:49224 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([D6C4F79DCF3F97A1:57227985B860F79D]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.AliasIntegrationTest.deleteAlias(AliasIntegrationTest.java:253)
at org.apache.solr.cloud.AliasIntegrationTest.doTest(AliasIntegrationTest.java:226)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:49498/rovu returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:49498/rovu returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([D6C4F79DCF3F97A1:57227985B860F79D]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9138 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.AliasIntegrationTest
[junit4:junit4] 2> 162500 T318 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 162514 T318 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./solrtest-AliasIntegrationTest-1372438089621
[junit4:junit4] 2> 162516 T318 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 162518 T319 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 162531 T318 oasc.ZkTestServer.run start zk server on port:49217
[junit4:junit4] 2> 162540 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 162547 T325 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@44013712 name:ZooKeeperConnection Watcher:127.0.0.1:49217 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 162548 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 162548 T318 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 162594 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 162598 T327 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43e304a3 name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 162599 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 162620 T318 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 162633 T318 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 162642 T318 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 162650 T318 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 162659 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 162660 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 162678 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 162680 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 162691 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 162692 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 162701 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 162703 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 162711 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 162712 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 162721 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 162722 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 162749 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 162750 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 162759 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 162760 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 162768 T318 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 162770 T318 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 163296 T318 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 163336 T318 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49220
[junit4:junit4] 2> 163337 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 163338 T318 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 163338 T318 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886
[junit4:junit4] 2> 163339 T318 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/solr.xml
[junit4:junit4] 2> 163339 T318 oasc.CoreContainer.<init> New CoreContainer 859847647
[junit4:junit4] 2> 163340 T318 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/'
[junit4:junit4] 2> 163341 T318 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/'
[junit4:junit4] 2> 163583 T318 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 163583 T318 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 163584 T318 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 163585 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 163585 T318 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 163586 T318 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 163586 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 163587 T318 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 163587 T318 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 163588 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 163614 T318 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 163615 T318 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49217/solr
[junit4:junit4] 2> 163637 T318 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 163639 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 163645 T338 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2576561b name:ZooKeeperConnection Watcher:127.0.0.1:49217 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 163646 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 163653 T320 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f8baf4fa30002, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 163659 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 163692 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 163698 T340 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@76a67dab name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 163699 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 163720 T318 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 163755 T318 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 163790 T318 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 163796 T318 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49220_
[junit4:junit4] 2> 163799 T318 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49220_
[junit4:junit4] 2> 163817 T318 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 163851 T318 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 163860 T318 oasc.Overseer.start Overseer (id=89944102642319363-127.0.0.1:49220_-n_0000000000) starting
[junit4:junit4] 2> 163895 T318 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 163939 T342 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 163951 T318 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 164008 T318 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 164030 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 164088 T341 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 164121 T343 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 164122 T343 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 164125 T343 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 165621 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 165637 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:49220_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49220"}
[junit4:junit4] 2> 165638 T341 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 165657 T341 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 165671 T340 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> 166143 T343 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 166144 T343 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection1
[junit4:junit4] 2> 166144 T343 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 166146 T343 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 166147 T343 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 166151 T343 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection1/'
[junit4:junit4] 2> 166152 T343 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 166153 T343 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection1/lib/README' to classloader
[junit4:junit4] 2> 166302 T343 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 166423 T343 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 166428 T343 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 166458 T343 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 168266 T343 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 168283 T343 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 168298 T343 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 168368 T343 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 168377 T343 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 168386 T343 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 168391 T343 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 168391 T343 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 168392 T343 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 168395 T343 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 168396 T343 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 168396 T343 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 168397 T343 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection1/, dataDir=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/control/data/
[junit4:junit4] 2> 168397 T343 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 168404 T343 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/control/data
[junit4:junit4] 2> 168404 T343 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/control/data/index/
[junit4:junit4] 2> 168406 T343 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.AliasIntegrationTest-1372438089620/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 168406 T343 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/control/data/index
[junit4:junit4] 2> 168412 T343 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67c860e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@69eb2cdb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 168412 T343 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 168491 T343 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 168491 T343 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 168492 T343 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 168493 T343 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 168494 T343 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 168495 T343 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 168495 T343 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 168496 T343 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 168497 T343 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 168512 T343 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 168520 T343 oass.SolrIndexSearcher.<init> Opening Searcher@1545dd25 main
[junit4:junit4] 2> 168522 T343 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 168523 T343 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 168541 T344 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1545dd25 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 168543 T343 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 168543 T343 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49220 collection:control_collection shard:shard1
[junit4:junit4] 2> 168558 T343 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 168586 T343 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 168624 T343 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 168634 T343 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 168634 T343 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 168640 T343 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49220/collection1/
[junit4:junit4] 2> 168641 T343 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 168642 T343 oasc.SyncStrategy.syncToMe http://127.0.0.1:49220/collection1/ has no replicas
[junit4:junit4] 2> 168642 T343 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49220/collection1/ shard1
[junit4:junit4] 2> 168643 T343 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 168731 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 168769 T340 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> 168786 T343 oasc.ZkController.register We are http://127.0.0.1:49220/collection1/ and leader is http://127.0.0.1:49220/collection1/
[junit4:junit4] 2> 168787 T343 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49220
[junit4:junit4] 2> 168787 T343 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 168788 T343 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 168788 T343 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 168812 T343 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 168819 T318 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 168819 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 168826 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 168878 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 168896 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 168901 T347 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10ea355b name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 168902 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 168916 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 168935 T318 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 169424 T318 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 169430 T318 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49224
[junit4:junit4] 2> 169432 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 169433 T318 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 169433 T318 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041
[junit4:junit4] 2> 169434 T318 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/solr.xml
[junit4:junit4] 2> 169434 T318 oasc.CoreContainer.<init> New CoreContainer 733552213
[junit4:junit4] 2> 169435 T318 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/'
[junit4:junit4] 2> 169436 T318 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/'
[junit4:junit4] 2> 169654 T318 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 169656 T318 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 169657 T318 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 169658 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 169658 T318 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 169659 T318 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 169660 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 169660 T318 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 169661 T318 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 169662 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 169693 T318 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 169694 T318 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49217/solr
[junit4:junit4] 2> 169695 T318 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 169698 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 169704 T358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cc94643 name:ZooKeeperConnection Watcher:127.0.0.1:49217 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 169705 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 169715 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 169744 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 169748 T360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b071630 name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 169749 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 169766 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 170296 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 170299 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:49220_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49220"}
[junit4:junit4] 2> 170316 T340 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> 170323 T347 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> 170324 T360 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> 170781 T318 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49224_
[junit4:junit4] 2> 170783 T318 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49224_
[junit4:junit4] 2> 170791 T347 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 170791 T347 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> 170795 T340 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> 170809 T360 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 170809 T360 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> 170812 T340 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 170832 T361 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 170833 T361 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 170836 T361 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 171841 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 171843 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49224_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49224"}
[junit4:junit4] 2> 171844 T341 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 171844 T341 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 171860 T340 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> 171872 T347 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> 171875 T360 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> 172838 T361 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 172839 T361 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection1
[junit4:junit4] 2> 172839 T361 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 172841 T361 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 172842 T361 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 172846 T361 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection1/'
[junit4:junit4] 2> 172847 T361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 172848 T361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection1/lib/README' to classloader
[junit4:junit4] 2> 172941 T361 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 173040 T361 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 173045 T361 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 173063 T361 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 174065 T361 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 174093 T361 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 174098 T361 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 174151 T361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 174184 T361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 174193 T361 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 174197 T361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 174198 T361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 174198 T361 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 174201 T361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 174202 T361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 174202 T361 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 174203 T361 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection1/, dataDir=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty1/
[junit4:junit4] 2> 174203 T361 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 174205 T361 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty1
[junit4:junit4] 2> 174231 T361 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty1/index/
[junit4:junit4] 2> 174231 T361 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 174232 T361 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty1/index
[junit4:junit4] 2> 174237 T361 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1672f0a6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18bdefd7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 174238 T361 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 174247 T361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 174248 T361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 174249 T361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 174250 T361 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 174258 T361 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 174259 T361 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 174260 T361 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 174261 T361 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 174262 T361 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 174277 T361 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 174298 T361 oass.SolrIndexSearcher.<init> Opening Searcher@51ea6fe1 main
[junit4:junit4] 2> 174300 T361 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 174301 T361 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 174308 T362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51ea6fe1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 174324 T361 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 174325 T361 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49224 collection:collection1 shard:shard1
[junit4:junit4] 2> 174356 T361 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 174396 T361 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 174413 T361 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 174413 T361 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 174414 T361 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49224/collection1/
[junit4:junit4] 2> 174415 T361 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 174415 T361 oasc.SyncStrategy.syncToMe http://127.0.0.1:49224/collection1/ has no replicas
[junit4:junit4] 2> 174415 T361 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49224/collection1/ shard1
[junit4:junit4] 2> 174416 T361 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 174925 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 174958 T340 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> 174961 T360 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> 174962 T347 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> 175002 T361 oasc.ZkController.register We are http://127.0.0.1:49224/collection1/ and leader is http://127.0.0.1:49224/collection1/
[junit4:junit4] 2> 175003 T361 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49224
[junit4:junit4] 2> 175004 T361 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 175004 T361 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 175004 T361 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 175010 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 175014 T318 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 175014 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 175015 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 175535 T318 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 175542 T318 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49227
[junit4:junit4] 2> 175543 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 175544 T318 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 175544 T318 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150
[junit4:junit4] 2> 175545 T318 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/solr.xml
[junit4:junit4] 2> 175546 T318 oasc.CoreContainer.<init> New CoreContainer 380687573
[junit4:junit4] 2> 175546 T318 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/'
[junit4:junit4] 2> 175547 T318 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/'
[junit4:junit4] 2> 175756 T318 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 175757 T318 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 175757 T318 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 175758 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 175758 T318 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 175759 T318 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 175759 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 175760 T318 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 175760 T318 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 175761 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 175783 T318 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 175784 T318 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49217/solr
[junit4:junit4] 2> 175785 T318 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 175791 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 175797 T374 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3dd764fe name:ZooKeeperConnection Watcher:127.0.0.1:49217 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 175798 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 175806 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 175832 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 175838 T376 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70d7c55c name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 175838 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 175859 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 176502 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 176506 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49224_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49224"}
[junit4:junit4] 2> 176528 T360 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> 176529 T347 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> 176537 T340 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> 176542 T376 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> 176871 T318 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49227_
[junit4:junit4] 2> 176875 T318 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49227_
[junit4:junit4] 2> 176888 T340 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> 176895 T340 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 176897 T360 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 176898 T360 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> 176904 T347 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 176904 T347 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> 176915 T376 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 176916 T376 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> 176934 T377 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 176934 T377 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 176951 T377 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 178064 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 178067 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49227_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49227"}
[junit4:junit4] 2> 178067 T341 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 178076 T341 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 178090 T340 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> 178091 T347 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> 178094 T360 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> 178102 T376 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> 178954 T377 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 178954 T377 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/collection1
[junit4:junit4] 2> 178954 T377 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 178956 T377 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 178956 T377 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 178962 T377 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/collection1/'
[junit4:junit4] 2> 178969 T377 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 178969 T377 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/collection1/lib/README' to classloader
[junit4:junit4] 2> 179043 T377 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 179136 T377 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 179140 T377 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 179157 T377 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 180158 T377 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 180182 T377 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 180188 T377 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 180369 T377 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 180388 T377 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 180397 T377 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 180400 T377 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 180401 T377 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 180402 T377 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 180405 T377 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 180406 T377 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 180406 T377 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 180407 T377 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty2-1372438102150/collection1/, dataDir=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty2/
[junit4:junit4] 2> 180407 T377 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 180409 T377 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty2
[junit4:junit4] 2> 180409 T377 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty2/index/
[junit4:junit4] 2> 180409 T377 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 180413 T377 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty2/index
[junit4:junit4] 2> 180424 T377 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4436f972 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63b276e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 180424 T377 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 180430 T377 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 180430 T377 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 180432 T377 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 180433 T377 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 180435 T377 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 180435 T377 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 180436 T377 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 180437 T377 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 180438 T377 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 180462 T377 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 180470 T377 oass.SolrIndexSearcher.<init> Opening Searcher@f69f10 main
[junit4:junit4] 2> 180472 T377 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 180472 T377 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 180487 T378 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f69f10 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 180492 T377 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 180492 T377 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49227 collection:collection1 shard:shard1
[junit4:junit4] 2> 180504 T377 oasc.ZkController.register We are http://127.0.0.1:49227/collection1/ and leader is http://127.0.0.1:49224/collection1/
[junit4:junit4] 2> 180505 T377 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49227
[junit4:junit4] 2> 180505 T377 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 180506 T377 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C213 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C213_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 180525 T379 C213 P49227 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 180526 T379 C213 P49227 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 180527 T379 C213 P49227 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 180527 T379 C213 P49227 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 180548 T379 C213 P49227 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 180568 T377 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 180636 T352 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 180641 T318 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 180642 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 180642 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 181106 T318 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 181117 T318 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49231
[junit4:junit4] 2> 181118 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 181119 T318 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 181119 T318 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764
[junit4:junit4] 2> 181120 T318 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/solr.xml
[junit4:junit4] 2> 181120 T318 oasc.CoreContainer.<init> New CoreContainer 1805127664
[junit4:junit4] 2> 181121 T318 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/'
[junit4:junit4] 2> 181122 T318 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/'
[junit4:junit4] 2> 181156 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 181158 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"1",
[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:49227_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49227"}
[junit4:junit4] 2> 181193 T340 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> 181193 T360 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> 181205 T376 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> 181209 T347 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> 181350 T318 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 181351 T318 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 181352 T318 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 181352 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 181353 T318 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 181354 T318 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 181354 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 181355 T318 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 181355 T318 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 181357 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 181380 T318 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 181381 T318 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49217/solr
[junit4:junit4] 2> 181381 T318 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 181385 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 181389 T391 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3072a301 name:ZooKeeperConnection Watcher:127.0.0.1:49217 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 181390 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 181395 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 181421 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 181426 T393 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20be8aed name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 181426 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 181439 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 181638 T352 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node2, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 181639 T352 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node2&state=recovering&nodeName=127.0.0.1:49227_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1009
[junit4:junit4] 2> 182450 T318 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49231_
[junit4:junit4] 2> 182453 T318 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49231_
[junit4:junit4] 2> 182460 T340 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> 182471 T360 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 182472 T360 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> 182478 T347 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 182478 T347 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> 182488 T376 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 182488 T376 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> 182497 T340 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 182501 T393 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 182510 T394 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 182510 T394 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 182513 T394 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 182720 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 182724 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49231_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49231"}
[junit4:junit4] 2> 182725 T341 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 182727 T341 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 182750 T340 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> 182751 T347 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> 182756 T393 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> 182756 T376 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> 182757 T360 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> 183515 T394 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 183516 T394 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/collection1
[junit4:junit4] 2> 183516 T394 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 183519 T394 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 183519 T394 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 183532 T394 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/collection1/'
[junit4:junit4] 2> 183534 T394 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 183534 T394 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/collection1/lib/README' to classloader
[junit4:junit4] 2> 183607 T394 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> ASYNC NEW_CORE C214 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C214_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 183642 T379 C214 P49227 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49224/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 183666 T379 C214 P49227 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 183709 T379 C214 P49227 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49227 START replicas=[http://127.0.0.1:49224/collection1/] nUpdates=100
[junit4:junit4] 2> 183714 T379 C214 P49227 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 183728 T379 C214 P49227 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 183730 T379 C214 P49227 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 183735 T379 C214 P49227 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 183735 T379 C214 P49227 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 183736 T379 C214 P49227 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49224/collection1/. core=collection1
[junit4:junit4] 2> 183736 T379 C214 P49227 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C215 name=collection1 org.apache.solr.core.SolrCore@623ff96d url=http://127.0.0.1:49224/collection1 node=127.0.0.1:49224_ C215_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 183785 T355 C215 P49224 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 183822 T394 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 183840 T394 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 183873 T394 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 184269 T356 C215 P49224 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 184329 T356 C215 P49224 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1672f0a6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18bdefd7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 184331 T356 C215 P49224 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 184331 T356 C215 P49224 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 184332 T356 C215 P49224 oass.SolrIndexSearcher.<init> Opening Searcher@3295cb9c realtime
[junit4:junit4] 2> 184333 T356 C215 P49224 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 184333 T356 C215 P49224 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 533
[junit4:junit4] 2> ASYNC NEW_CORE C216 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C216_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 184335 T379 C216 P49227 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 184336 T379 C216 P49227 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> ASYNC NEW_CORE C217 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C217_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 184441 T379 C217 P49227 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> ASYNC NEW_CORE C218 name=collection1 org.apache.solr.core.SolrCore@623ff96d url=http://127.0.0.1:49224/collection1 node=127.0.0.1:49224_ C218_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 184453 T354 C218 P49224 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 184454 T354 C218 P49224 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 184459 T379 C217 P49227 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 184460 T379 C217 P49227 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 184460 T379 C217 P49227 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 184460 T379 C217 P49227 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 184473 T379 C217 P49227 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 185357 T394 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 185380 T394 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 185386 T394 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 185440 T394 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 185449 T394 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 185484 T394 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 185489 T394 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 185491 T394 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 185491 T394 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 185495 T394 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 185496 T394 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 185496 T394 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 185497 T394 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty3-1372438107764/collection1/, dataDir=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty3/
[junit4:junit4] 2> 185497 T394 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 185498 T394 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty3
[junit4:junit4] 2> 185499 T394 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty3/index/
[junit4:junit4] 2> 185499 T394 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 185500 T394 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty3/index
[junit4:junit4] 2> 185506 T394 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@447088aa lockFactory=org.apache.lucene.store.NativeFSLockFactory@4472abe8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 185506 T394 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 185511 T394 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 185512 T394 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 185513 T394 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 185514 T394 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 185516 T394 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 185516 T394 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 185523 T394 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 185524 T394 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 185525 T394 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 185539 T394 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 185556 T394 oass.SolrIndexSearcher.<init> Opening Searcher@417e412c main
[junit4:junit4] 2> 185558 T394 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 185558 T394 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 185566 T396 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@417e412c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 185581 T394 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 185582 T394 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49231 collection:collection1 shard:shard1
[junit4:junit4] 2> 185594 T394 oasc.ZkController.register We are http://127.0.0.1:49231/collection1/ and leader is http://127.0.0.1:49224/collection1/
[junit4:junit4] 2> 185595 T394 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49231
[junit4:junit4] 2> 185597 T394 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 185598 T394 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C219 name=collection1 org.apache.solr.core.SolrCore@33f5c786 url=http://127.0.0.1:49231/collection1 node=127.0.0.1:49231_ C219_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:49231_, base_url=http://127.0.0.1:49231}
[junit4:junit4] 2> 185598 T397 C219 P49231 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 185600 T397 C219 P49231 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 185600 T397 C219 P49231 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 185600 T397 C219 P49231 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 185631 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 185638 T397 C219 P49231 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 185662 T318 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 185666 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 185667 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 185692 T356 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 185839 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 185842 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49227_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49227"}
[junit4:junit4] 2> 185854 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"1",
[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:49231_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49231"}
[junit4:junit4] 2> 185885 T393 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> 185885 T347 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> 185885 T360 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> 185885 T376 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> 185896 T340 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> 186339 T318 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 186353 T318 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49238
[junit4:junit4] 2> 186355 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 186356 T318 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 186356 T318 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830
[junit4:junit4] 2> 186358 T318 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/solr.xml
[junit4:junit4] 2> 186358 T318 oasc.CoreContainer.<init> New CoreContainer 1511848054
[junit4:junit4] 2> 186359 T318 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/'
[junit4:junit4] 2> 186359 T318 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/'
[junit4:junit4] 2> 186553 T318 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 186554 T318 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 186555 T318 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 186555 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 186556 T318 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 186556 T318 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 186557 T318 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 186557 T318 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 186558 T318 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 186558 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 186579 T318 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 186580 T318 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:49217/solr
[junit4:junit4] 2> 186581 T318 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 186583 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 186590 T409 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1066d85f name:ZooKeeperConnection Watcher:127.0.0.1:49217 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 186590 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 186597 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 186621 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 186626 T411 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a897294 name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 186626 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 186642 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 186696 T356 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 186710 T356 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:49231_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1018
[junit4:junit4] 2> 187658 T318 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49238_
[junit4:junit4] 2> 187661 T318 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49238_
[junit4:junit4] 2> 187669 T340 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> 187675 T393 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 187675 T393 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> 187686 T340 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 187699 T376 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 187700 T376 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> 187712 T360 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 187713 T360 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> 187727 T411 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 187738 T347 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 187738 T347 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> 187741 T412 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 187741 T412 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 187750 T412 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> ASYNC NEW_CORE C220 name=collection1 org.apache.solr.core.SolrCore@33f5c786 url=http://127.0.0.1:49231/collection1 node=127.0.0.1:49231_ C220_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:49231_, base_url=http://127.0.0.1:49231}
[junit4:junit4] 2> 188712 T397 C220 P49231 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49224/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 188713 T397 C220 P49231 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49231 START replicas=[http://127.0.0.1:49224/collection1/] nUpdates=100
[junit4:junit4] 2> 188715 T397 C220 P49231 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 188715 T397 C220 P49231 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 188715 T397 C220 P49231 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 188716 T397 C220 P49231 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 188716 T397 C220 P49231 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 188718 T397 C220 P49231 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49224/collection1/. core=collection1
[junit4:junit4] 2> 188718 T397 C220 P49231 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C221 name=collection1 org.apache.solr.core.SolrCore@623ff96d url=http://127.0.0.1:49224/collection1 node=127.0.0.1:49224_ C221_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 188754 T355 C221 P49224 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 188759 T351 C221 P49224 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 188760 T351 C221 P49224 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 188760 T351 C221 P49224 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 188761 T351 C221 P49224 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 3
[junit4:junit4] 2> 188763 T397 C220 P49231 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 188764 T397 C220 P49231 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 188769 T354 C221 P49224 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 188771 T397 C220 P49231 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 188771 T397 C220 P49231 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 188771 T397 C220 P49231 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 188772 T397 C220 P49231 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 188775 T397 C220 P49231 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 188930 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 188933 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49238_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49238"}
[junit4:junit4] 2> 188933 T341 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 188934 T341 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 188948 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49231_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49231"}
[junit4:junit4] 2> 188968 T393 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> 188968 T376 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> 188970 T340 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> 188981 T411 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> 188983 T347 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> 188971 T360 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> 189759 T412 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 189760 T412 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/collection1
[junit4:junit4] 2> 189760 T412 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 189762 T412 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 189762 T412 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 189767 T412 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/collection1/'
[junit4:junit4] 2> 189769 T412 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 189769 T412 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/collection1/lib/README' to classloader
[junit4:junit4] 2> 189894 T412 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 190034 T412 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 190044 T412 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 190062 T412 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 191130 T412 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 191160 T412 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 191164 T412 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 191323 T412 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 191333 T412 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 191363 T412 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 191396 T412 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 191397 T412 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 191397 T412 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 191405 T412 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 191406 T412 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 191407 T412 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 191407 T412 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty4-1372438112830/collection1/, dataDir=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty4/
[junit4:junit4] 2> 191408 T412 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 191410 T412 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty4
[junit4:junit4] 2> 191411 T412 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty4/index/
[junit4:junit4] 2> 191411 T412 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 191412 T412 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.AliasIntegrationTest-1372438089620/jetty4/index
[junit4:junit4] 2> 191417 T412 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31cfbd76 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21602963),segFN=segments_1,generation=1}
[junit4:junit4] 2> 191417 T412 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 191421 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 191422 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 191423 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 191424 T412 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 191426 T412 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 191426 T412 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 191428 T412 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 191429 T412 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 191429 T412 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 191444 T412 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 191454 T412 oass.SolrIndexSearcher.<init> Opening Searcher@5f9aa8db main
[junit4:junit4] 2> 191455 T412 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 191456 T412 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 191464 T414 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5f9aa8db main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 191469 T412 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 191469 T412 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49238 collection:collection1 shard:shard1
[junit4:junit4] 2> 191478 T412 oasc.ZkController.register We are http://127.0.0.1:49238/collection1/ and leader is http://127.0.0.1:49224/collection1/
[junit4:junit4] 2> 191479 T412 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49238
[junit4:junit4] 2> 191479 T412 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 191480 T412 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C222 name=collection1 org.apache.solr.core.SolrCore@73fb57df url=http://127.0.0.1:49238/collection1 node=127.0.0.1:49238_ C222_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:49238_, base_url=http://127.0.0.1:49238}
[junit4:junit4] 2> 191481 T415 C222 P49238 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 191482 T415 C222 P49238 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 191482 T415 C222 P49238 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 191483 T415 C222 P49238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 191500 T412 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 191500 T415 C222 P49238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 191530 T318 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 191531 T318 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 191531 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 191567 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 191569 T352 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 191572 T318 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 191573 T318 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 191575 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 192088 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 192091 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"1",
[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:49238_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49238"}
[junit4:junit4] 2> 192106 T376 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> 192106 T360 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> 192111 T340 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> 192113 T411 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> 192114 T393 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> 192115 T347 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> 192571 T352 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 192572 T352 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:49238_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 192583 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 193588 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C223 name=collection1 org.apache.solr.core.SolrCore@73fb57df url=http://127.0.0.1:49238/collection1 node=127.0.0.1:49238_ C223_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:49238_, base_url=http://127.0.0.1:49238}
[junit4:junit4] 2> 194574 T415 C223 P49238 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49224/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 194575 T415 C223 P49238 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49238 START replicas=[http://127.0.0.1:49224/collection1/] nUpdates=100
[junit4:junit4] 2> 194576 T415 C223 P49238 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 194576 T415 C223 P49238 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 194577 T415 C223 P49238 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 194577 T415 C223 P49238 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 194577 T415 C223 P49238 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 194579 T415 C223 P49238 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49224/collection1/. core=collection1
[junit4:junit4] 2> 194580 T415 C223 P49238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 194604 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C224 name=collection1 org.apache.solr.core.SolrCore@623ff96d url=http://127.0.0.1:49224/collection1 node=127.0.0.1:49224_ C224_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 194610 T352 C224 P49224 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> 194620 T353 C224 P49224 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 194621 T353 C224 P49224 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 194621 T353 C224 P49224 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 194622 T353 C224 P49224 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 2
[junit4:junit4] 2> 194624 T415 C223 P49238 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 194624 T415 C223 P49238 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 194631 T356 C224 P49224 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 194632 T415 C223 P49238 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 194633 T415 C223 P49238 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 194633 T415 C223 P49238 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 194633 T415 C223 P49238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 194637 T415 C223 P49238 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 195149 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 195151 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[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":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49238_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49238"}
[junit4:junit4] 2> 195166 T393 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> 195167 T376 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> 195168 T411 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> 195168 T360 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> 195169 T347 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> 195168 T340 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> 195620 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 195626 T318 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C225 name=collection1 org.apache.solr.core.SolrCore@1fd422e5 url=http://127.0.0.1:49220/collection1 node=127.0.0.1:49220_ C225_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49220_, base_url=http://127.0.0.1:49220, leader=true}
[junit4:junit4] 2> 195678 T331 C225 P49220 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 195682 T331 C225 P49220 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@67c860e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@69eb2cdb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 195683 T331 C225 P49220 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 195685 T331 C225 P49220 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 195685 T331 C225 P49220 oass.SolrIndexSearcher.<init> Opening Searcher@415c7850 main
[junit4:junit4] 2> 195686 T331 C225 P49220 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 195688 T344 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@415c7850 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 195691 T331 C225 P49220 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> C223_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49238_, base_url=http://127.0.0.1:49238}
[junit4:junit4] 2> 195759 T402 C223 P49238 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:49224/collection1/, StdNode: http://127.0.0.1:49227/collection1/, StdNode: http://127.0.0.1:49231/collection1/, StdNode: http://127.0.0.1:49238/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 195811 T403 C223 P49238 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 195813 T353 C224 P49224 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 195814 T353 C224 P49224 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 195814 T353 C224 P49224 oass.SolrIndexSearcher.<init> Opening Searcher@3bb4be09 main
[junit4:junit4] 2> 195815 T353 C224 P49224 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 195829 T362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3bb4be09 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 195830 T353 C224 P49224 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 2> 195834 T403 C223 P49238 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31cfbd76 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21602963),segFN=segments_1,generation=1}
[junit4:junit4] 2> ASYNC NEW_CORE C226 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C226_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 195846 T368 C226 P49227 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C227 name=collection1 org.apache.solr.core.SolrCore@33f5c786 url=http://127.0.0.1:49231/collection1 node=127.0.0.1:49231_ C227_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49231_, base_url=http://127.0.0.1:49231}
[junit4:junit4] 2> 195848 T389 C227 P49231 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 195853 T368 C226 P49227 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4436f972 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63b276e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 195855 T389 C227 P49231 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@447088aa lockFactory=org.apache.lucene.store.NativeFSLockFactory@4472abe8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 195856 T403 C223 P49238 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 195857 T403 C223 P49238 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 195858 T368 C226 P49227 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 195858 T368 C226 P49227 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 195860 T368 C226 P49227 oass.SolrIndexSearcher.<init> Opening Searcher@42296d15 main
[junit4:junit4] 2> 195860 T368 C226 P49227 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 195861 T389 C227 P49231 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 195861 T389 C227 P49231 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 195874 T403 C223 P49238 oass.SolrIndexSearcher.<init> Opening Searcher@33f85c21 main
[junit4:junit4] 2> 195876 T403 C223 P49238 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 195864 T378 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@42296d15 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 195878 T414 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@33f85c21 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 195889 T368 C226 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 43
[junit4:junit4] 2> 195889 T403 C223 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 78
[junit4:junit4] 2> 195893 T389 C227 P49231 oass.SolrIndexSearcher.<init> Opening Searcher@68a33067 main
[junit4:junit4] 2> 195895 T389 C227 P49231 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 195896 T396 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@68a33067 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 195896 T389 C227 P49231 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 48
[junit4:junit4] 2> 195898 T402 C223 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 147
[junit4:junit4] 2> 195915 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 195922 T356 C224 P49224 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 195936 T369 C226 P49227 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 195960 T384 C227 P49231 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 195973 T404 C223 P49238 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 198000 T331 C225 P49220 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439105679466954752)} 0 11
[junit4:junit4] 2> 198082 T368 C226 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439105679533015040&update.from=http://127.0.0.1:49224/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439105679533015040)} 0 10
[junit4:junit4] 2> 198106 T405 C223 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439105679533015040&update.from=http://127.0.0.1:49224/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439105679533015040)} 0 18
[junit4:junit4] 2> 198113 T385 C227 P49231 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439105679533015040&update.from=http://127.0.0.1:49224/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439105679533015040)} 0 4
[junit4:junit4] 2> 198118 T356 C224 P49224 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439105679533015040)} 0 58
[junit4:junit4] 2> 198121 T404 C223 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 84
[junit4:junit4] 2> 198128 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 198258 T370 oasha.CollectionsHandler.handleCreateAction Creating Collection : numShards=2&maxShardsPerNode=10&name=collection2&replicationFactor=1&action=CREATE&wt=javabin&version=2
[junit4:junit4] 2> 198291 T340 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 198301 T342 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Get the message id:/overseer/collection-queue-work/qn-0000000000 message:{
[junit4:junit4] 2> "operation":"createcollection",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "maxShardsPerNode":"10",
[junit4:junit4] 2> "createNodeSet":null,
[junit4:junit4] 2> "name":"collection2",
[junit4:junit4] 2> "replicationFactor":"1"}
[junit4:junit4] 2> 198302 T342 oasc.OverseerCollectionProcessor.createCollection Creating shard collection2_shard1_replica1 as part of slice shard1 of collection collection2 on 127.0.0.1:49224_
[junit4:junit4] 2> 198303 T342 oasc.OverseerCollectionProcessor.createCollection Creating shard collection2_shard2_replica1 as part of slice shard2 of collection collection2 on 127.0.0.1:49220_
[junit4:junit4] 2> 198312 T355 oasc.ZkController.publish publishing core=collection2_shard1_replica1 state=down
[junit4:junit4] 2> 198328 T333 oasc.ZkController.publish publishing core=collection2_shard2_replica1 state=down
[junit4:junit4] 2> 198337 T355 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 198340 T333 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 199717 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 199720 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection2_shard1_replica1",
[junit4:junit4] 2> "collection":"collection2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49224_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49224"}
[junit4:junit4] 2> 199720 T341 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection2 with numShards 2
[junit4:junit4] 2> 199731 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection2_shard2_replica1",
[junit4:junit4] 2> "collection":"collection2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49220_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49220"}
[junit4:junit4] 2> 199745 T376 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> 199745 T340 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> 199746 T347 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> 199769 T393 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> 199775 T411 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> 199776 T360 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> 200342 T355 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection2_shard1_replica1
[junit4:junit4] 2> 200343 T355 oasc.CoreContainer.create Creating SolrCore 'collection2_shard1_replica1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1
[junit4:junit4] 2> 200344 T355 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection2
[junit4:junit4] 2> 200345 T333 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection2_shard2_replica1
[junit4:junit4] 2> 200345 T333 oasc.CoreContainer.create Creating SolrCore 'collection2_shard2_replica1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1
[junit4:junit4] 2> 200346 T333 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection2
[junit4:junit4] 2> 200349 T355 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:collection2
[junit4:junit4] 2> 200350 T355 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 200355 T355 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 200356 T355 oascc.SolrZkClient.makePath makePath: /collections/collection2
[junit4:junit4] 2> 200357 T333 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:collection2
[junit4:junit4] 2> 200358 T333 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 200361 T333 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 200362 T333 oascc.SolrZkClient.makePath makePath: /collections/collection2
[junit4:junit4] 2> 200377 T333 oasc.ZkController.readConfigName Load collection config from:/collections/collection2
[junit4:junit4] 2> 200381 T355 oasc.ZkController.readConfigName Load collection config from:/collections/collection2
[junit4:junit4] 2> 200385 T333 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/'
[junit4:junit4] 2> 200385 T355 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/'
[junit4:junit4] 2> 200526 T355 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 200571 T333 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 200733 T355 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 200737 T333 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 200740 T355 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 200751 T355 oass.IndexSchema.readSchema [collection2_shard1_replica1] Schema name=test
[junit4:junit4] 2> 200782 T333 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 200794 T333 oass.IndexSchema.readSchema [collection2_shard2_replica1] Schema name=test
[junit4:junit4] 2> 202354 T355 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 202387 T355 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 202394 T355 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 202422 T333 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 202443 T333 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 202456 T333 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 202525 T333 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 202527 T355 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 202535 T333 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 202536 T355 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 202548 T355 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 202570 T355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 202571 T355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 202574 T355 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 202581 T355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 202582 T355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 202582 T355 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 202583 T355 oasc.SolrCore.<init> [collection2_shard1_replica1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/data/
[junit4:junit4] 2> 202584 T355 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 202585 T355 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/data
[junit4:junit4] 2> 202586 T355 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/data/index/
[junit4:junit4] 2> 202586 T355 oasc.SolrCore.initIndex WARN [collection2_shard1_replica1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 202588 T355 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-jetty1-1372438096041/collection2_shard1_replica1/data/index
[junit4:junit4] 2> 202592 T333 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 202597 T355 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29b586fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff0678c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 202598 T355 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 202615 T355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 202616 T355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 202617 T355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 202619 T333 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 202619 T333 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 202620 T333 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 202621 T355 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 202622 T355 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 202622 T355 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 202623 T355 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 202624 T355 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 202625 T355 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 202657 T333 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 202658 T333 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 202658 T333 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 202659 T333 oasc.SolrCore.<init> [collection2_shard2_replica1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/, dataDir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/data/
[junit4:junit4] 2> 202664 T355 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 202665 T333 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@44385e76
[junit4:junit4] 2> 202685 T355 oass.SolrIndexSearcher.<init> Opening Searcher@34cc2998 main
[junit4:junit4] 2> 202691 T355 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 202691 T355 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 202697 T427 oasc.SolrCore.registerSearcher [collection2_shard1_replica1] Registered new searcher Searcher@34cc2998 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 202689 T333 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/data
[junit4:junit4] 2> 202700 T355 oasc.CoreContainer.registerCore registering core: collection2_shard1_replica1
[junit4:junit4] 2> 202700 T355 oasc.ZkController.register Register replica - core:collection2_shard1_replica1 address:http://127.0.0.1:49224 collection:collection2 shard:shard1
[junit4:junit4] 2> 202703 T333 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/data/index/
[junit4:junit4] 2> 202707 T333 oasc.SolrCore.initIndex WARN [collection2_shard2_replica1] Solr index directory '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 202708 T355 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard1/election
[junit4:junit4] 2> 202708 T333 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.AliasIntegrationTest-controljetty-1372438089886/collection2_shard2_replica1/data/index
[junit4:junit4] 2> 202717 T333 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ead8de4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a2667e0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 202718 T333 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 202723 T333 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 202724 T333 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 202725 T333 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 202727 T333 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 202728 T333 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 202729 T333 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 202729 T333 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 202730 T333 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 202732 T333 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 202733 T355 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 202754 T333 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 202763 T333 oass.SolrIndexSearcher.<init> Opening Searcher@6b583cc9 main
[junit4:junit4] 2> 202765 T333 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 202765 T333 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 202772 T428 oasc.SolrCore.registerSearcher [collection2_shard2_replica1] Registered new searcher Searcher@6b583cc9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 202778 T333 oasc.CoreContainer.registerCore registering core: collection2_shard2_replica1
[junit4:junit4] 2> 202782 T333 oasc.ZkController.register Register replica - core:collection2_shard2_replica1 address:http://127.0.0.1:49220 collection:collection2 shard:shard2
[junit4:junit4] 2> 202785 T333 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard2/election
[junit4:junit4] 2> 202789 T355 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 202789 T355 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 202790 T355 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49224/collection2_shard1_replica1/
[junit4:junit4] 2> 202791 T355 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 202791 T355 oasc.SyncStrategy.syncToMe http://127.0.0.1:49224/collection2_shard1_replica1/ has no replicas
[junit4:junit4] 2> 202791 T355 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49224/collection2_shard1_replica1/ shard1
[junit4:junit4] 2> 202792 T355 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard1
[junit4:junit4] 2> 202816 T333 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4:junit4] 2> 202829 T333 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 202830 T333 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 202830 T333 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49220/collection2_shard2_replica1/
[junit4:junit4] 2> 202831 T333 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 202836 T333 oasc.SyncStrategy.syncToMe http://127.0.0.1:49220/collection2_shard2_replica1/ has no replicas
[junit4:junit4] 2> 202836 T333 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49220/collection2_shard2_replica1/ shard2
[junit4:junit4] 2> 202837 T333 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard2
[junit4:junit4] 2> 202859 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 202916 T393 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> 202917 T411 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> 202920 T376 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> 202921 T347 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> 202921 T340 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> 202924 T360 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> 202984 T355 oasc.ZkController.register We are http://127.0.0.1:49224/collection2_shard1_replica1/ and leader is http://127.0.0.1:49224/collection2_shard1_replica1/
[junit4:junit4] 2> 202985 T355 oasc.ZkController.register No LogReplay needed for core=collection2_shard1_replica1 baseURL=http://127.0.0.1:49224
[junit4:junit4] 2> 202985 T355 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 202987 T355 oasc.ZkController.publish publishing core=collection2_shard1_replica1 state=active
[junit4:junit4] 2> 202989 T333 oasc.ZkController.register We are http://127.0.0.1:49220/collection2_shard2_replica1/ and leader is http://127.0.0.1:49220/collection2_shard2_replica1/
[junit4:junit4] 2> 202990 T333 oasc.ZkController.register No LogReplay needed for core=collection2_shard2_replica1 baseURL=http://127.0.0.1:49220
[junit4:junit4] 2> 202991 T333 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 202991 T333 oasc.ZkController.publish publishing core=collection2_shard2_replica1 state=active
[junit4:junit4] 2> 202997 T355 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 202999 T333 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 203002 T355 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard1&name=collection2_shard1_replica1&action=CREATE&collection=collection2&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=4690
[junit4:junit4] 2> 203003 T333 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={numShards=2&shard=shard2&name=collection2_shard2_replica1&action=CREATE&collection=collection2&wt=javabin&qt=/admin/cores&version=2} status=0 QTime=4675
[junit4:junit4] 2> 203007 T342 oasc.OverseerCollectionProcessor.createCollection Finished create command on all shards for collection: collection2
[junit4:junit4] 2> 203074 T376 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work/qnr-0000000000 state: SyncConnected type NodeDataChanged
[junit4:junit4] 2> 203088 T370 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={numShards=2&maxShardsPerNode=10&name=collection2&replicationFactor=1&action=CREATE&wt=javabin&version=2} status=0 QTime=4841
[junit4:junit4] 2> 203090 T318 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 203092 T318 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 203093 T340 oasc.DistributedQueue$LatchChildWatcher.process Watcher fired on path: /overseer/collection-queue-work state: SyncConnected type NodeChildrenChanged
[junit4:junit4] 2> 203099 T430 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cebdec4 name:ZooKeeperConnection Watcher:127.0.0.1:49217/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 203099 T318 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 203110 T318 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 203111 T342 oasc.OverseerCollectionProcessor.run Overseer Collection Processor: Message id:/overseer/collection-queue-work/qn-0000000000 complete, response:{success={null={responseHeader={status=0,QTime=4690},core=collection2_shard1_replica1},null={responseHeader={status=0,QTime=4675},core=collection2_shard2_replica1}}}
[junit4:junit4] 2> 203119 T318 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection2 failOnTimeout:true timeout (sec):330
[junit4:junit4] 2> 203121 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 204127 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 204464 T341 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 204467 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"2",
[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":"collection2_shard1_replica1",
[junit4:junit4] 2> "collection":"collection2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49224_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49224"}
[junit4:junit4] 2> 204478 T341 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"2",
[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":"collection2_shard2_replica1",
[junit4:junit4] 2> "collection":"collection2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49220_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49220"}
[junit4:junit4] 2> 204494 T376 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> 204495 T340 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> 204495 T393 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> 204496 T347 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> 204498 T430 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> 204500 T411 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> 204501 T360 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> 205131 T318 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 205134 T318 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection2
[junit4:junit4] 2> ASYNC NEW_CORE C228 name=collection1 org.apache.solr.core.SolrCore@33f5c786 url=http://127.0.0.1:49231/collection1 node=127.0.0.1:49231_ C228_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49231_, base_url=http://127.0.0.1:49231}
[junit4:junit4] 2> 205197 T384 C228 P49231 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1439105686975807488)]} 0 15
[junit4:junit4] 2> ASYNC NEW_CORE C229 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C229_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 205198 T370 C229 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1439105686975807488)]} 0 6
[junit4:junit4] 2> ASYNC NEW_CORE C230 name=collection1 org.apache.solr.core.SolrCore@73fb57df url=http://127.0.0.1:49238/collection1 node=127.0.0.1:49238_ C230_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49238_, base_url=http://127.0.0.1:49238}
[junit4:junit4] 2> 205198 T406 C230 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1439105686975807488)]} 0 8
[junit4:junit4] 2> ASYNC NEW_CORE C231 name=collection1 org.apache.solr.core.SolrCore@623ff96d url=http://127.0.0.1:49224/collection1 node=127.0.0.1:49224_ C231_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 205231 T355 C231 P49224 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49238/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1439105686975807488)]} 0 73
[junit4:junit4] 2> 205233 T404 C230 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 95
[junit4:junit4] 2> 205263 T407 C230 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1439105687071227904)]} 0 3
[junit4:junit4] 2> 205274 T367 C229 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1439105687071227904)]} 0 14
[junit4:junit4] 2> 205276 T385 C228 P49231 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1439105687071227904)]} 0 7
[junit4:junit4] 2> 205304 T352 C231 P49224 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1439105687071227904)]} 0 56
[junit4:junit4] 2> 205325 T386 C228 P49231 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1439105687135191040)]} 0 2
[junit4:junit4] 2> 205330 T368 C229 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1439105687135191040)]} 0 2
[junit4:junit4] 2> 205334 T403 C230 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:49224/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1439105687135191040)]} 0 2
[junit4:junit4] 2> 205344 T353 C231 P49224 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1439105687135191040)]} 0 34
[junit4:junit4] 2> 205350 T369 C229 P49227 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:49224/collection1/, StdNode: http://127.0.0.1:49227/collection1/, StdNode: http://127.0.0.1:49231/collection1/, StdNode: http://127.0.0.1:49238/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 205388 T387 C228 P49231 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C232 name=collection1 org.apache.solr.core.SolrCore@3076f54c url=http://127.0.0.1:49227/collection1 node=127.0.0.1:49227_ C232_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49227_, base_url=http://127.0.0.1:49227}
[junit4:junit4] 2> 205412 T371 C232 P49227 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C233 name=collection1 org.apache.solr.core.SolrCore@73fb57df url=http://127.0.0.1:49238/collection1 node=127.0.0.1:49238_ C233_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49238_, base_url=http://127.0.0.1:49238}
[junit4:junit4] 2> 205414 T402 C233 P49238 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C234 name=collection1 org.apache.solr.core.SolrCore@623ff96d url=http://127.0.0.1:49224/collection1 node=127.0.0.1:49224_ C234_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 205415 T354 C234 P49224 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C235 name=collection1 org.apache.solr.core.SolrCore@33f5c786 url=http://127.0.0.1:49231/collection1 node=127.0.0.1:49231_ C235_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49231_, base_url=http://127.0.0.1:49231}
[junit4:junit4] 2> 205660 T387 C235 P49231 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@447088aa lockFactory=org.apache.lucene.store.NativeFSLockFactory@4472abe8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@447088aa lockFactory=org.apache.lucene.store.NativeFSLockFactory@4472abe8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 205661 T387 C235 P49231 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 205681 T402 C233 P49238 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31cfbd76 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21602963),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@31cfbd76 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21602963),segFN=segments_2,generation=2}
[junit4:junit4] 2> 205682 T402 C233 P49238 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 205801 T402 C233 P49238 oass.SolrIndexSearcher.<init> Opening Searcher@35acd991 main
[junit4:junit4] 2> 205802 T402 C233 P49238 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 205803 T414 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35acd991 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C3)}
[junit4:junit4] 2> 205813 T402 C233 P49238 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 400
[junit4:junit4] 2> 205831 T387 C235 P49231 oass.SolrIndexSearcher.<init> Opening Searcher@16a6cf56 main
[junit4:junit4] 2> 205834 T396 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16a6cf56 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C3)}
[junit4:junit4] 2> 205835 T387 C235 P49231 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 205835 T387 C235 P49231 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 447
[junit4:junit4] 2> 205849 T371 C232 P49227 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4436f972 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63b276e),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4436f972 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63b276e),segFN=segments_2,generation=2}
[junit4:junit4] 2> 205850 T371 C232 P49227 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 205859 T354 C234 P49224 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1672f0a6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18bdefd7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1672f0a6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18bdefd7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 205865 T354 C234 P49224 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 205891 T371 C232 P49227 oass.SolrIndexSearcher.<init> Opening Searcher@16041baf main
[junit4:junit4] 2> 205899 T371 C232 P49227 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 205901 T378 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16041baf main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C3)}
[junit4:junit4] 2> 205907 T371 C232 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 495
[junit4:junit4] 2> 205923 T354 C234 P49224 oass.SolrIndexSearcher.<init> Opening Searcher@5de5ffa4 main
[junit4:junit4] 2> 205927 T362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5de5ffa4 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C3)}
[junit4:junit4] 2> 205930 T354 C234 P49224 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 205930 T354 C234 P49224 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 516
[junit4:junit4] 2> 205932 T369 C232 P49227 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 583
[junit4:junit4] 2> ASYNC NEW_CORE C236 name=collection2_shard2_replica1 org.apache.solr.core.SolrCore@1ca3acfe url=http://127.0.0.1:49220/collection2_shard2_replica1 node=127.0.0.1:49220_ C236_STATE=coll:collection2 core:collection2_shard2_replica1 props:{state=active, core=collection2_shard2_replica1, node_name=127.0.0.1:49220_, base_url=http://127.0.0.1:49220, leader=true}
[junit4:junit4] 2> 205970 T335 C236 P49220 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ead8de4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a2667e0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 205972 T335 C236 P49220 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 205992 T335 C236 P49220 oasup.LogUpdateProcessor.finish [collection2_shard2_replica1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1439105687801036800)]} 0 47
[junit4:junit4] 2> ASYNC NEW_CORE C237 name=collection2_shard1_replica1 org.apache.solr.core.SolrCore@162382a5 url=http://127.0.0.1:49224/collection2_shard1_replica1 node=127.0.0.1:49224_ C237_STATE=coll:collection2 core:collection2_shard1_replica1 props:{state=active, core=collection2_shard1_replica1, node_name=127.0.0.1:49224_, base_url=http://127.0.0.1:49224, leader=true}
[junit4:junit4] 2> 206061 T351 C237 P49224 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29b586fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff0678c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 206062 T351 C237 P49224 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 206070 T351 C237 P49224 oasup.LogUpdateProcessor.finish [collection2_shard1_replica1] webapp= path=/update params={distrib.from=http://127.0.0.1:49220/collection2_shard2_replica1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1439105687871291392)]} 0 59
[junit4:junit4] 2> 206072 T336 C236 P49220 oasup.LogUpdateProcessor.finish [collection2_shard2_replica1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 76
[junit4:junit4] 2> 206076 T355 C237 P49224 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:49224/collection2_shard1_replica1/, StdNode: http://127.0.0.1:49220/collection2_shard2_replica1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 206093 T352 C237 P49224 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 206095 T331 C236 P49220 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 206357 T352 C237 P49224 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29b586fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff0678c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@29b586fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ff0678c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 206357 T352 C237 P49224 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 206359 T331 C236 P49220 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ead8de4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a2667e0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ead8de4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a2667e0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 206360 T331 C236 P49220 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 206368 T352 C237 P49224 oass.SolrIndexSearcher.<init> Opening Searcher@47111447 main
[junit4:junit4] 2> 206376 T427 oasc.SolrCore.registerSearcher [collection2_shard1_replica1] Registered new searcher Searcher@47111447 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C1)}
[junit4:junit4] 2> 206403 T352 C237 P49224 oasu.DirectUpdateHandler2.commit end_commit_flush
[
[...truncated too long message...]
ive",
[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:49504_rovu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49504/rovu"}
[junit4:junit4] 2> 619076 T1176 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> 619094 T1085 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 49508
[junit4:junit4] 2> 619095 T1085 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1760165217
[junit4:junit4] 2> 620104 T1085 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 620105 T1085 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 620109 T1085 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@59753857
[junit4:junit4] 2> 620125 T1085 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=228,adds=228,deletesById=115,deletesByQuery=0,errors=0,cumulative_adds=270,cumulative_deletesById=115,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 620126 T1085 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 620127 T1085 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 620127 T1085 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> ASYNC NEW_CORE C626 name=collection1 org.apache.solr.core.SolrCore@59753857 url=http://127.0.0.1:49508/rovu/collection1 node=127.0.0.1:49508_rovu C626_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:49508_rovu, base_url=http://127.0.0.1:49508/rovu, leader=true}
[junit4:junit4] 2> 620234 T1085 C626 P49508 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f2e88b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@605f6f30),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f2e88b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@605f6f30),segFN=segments_3,generation=3}
[junit4:junit4] 2> 620235 T1085 C626 P49508 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 620253 T1085 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 620254 T1085 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 620254 T1085 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372438453439/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372438453439/jetty4;done=false>>]
[junit4:junit4] 2> 620255 T1085 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372438453439/jetty4
[junit4:junit4] 2> 620262 T1085 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1372438453439/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1372438453439/jetty4/index;done=false>>]
[junit4:junit4] 2> 620263 T1085 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1372438453439/jetty4/index
[junit4:junit4] 2> 620263 T1159 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 620276 T1159 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> 620277 T1159 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 620278 T1207 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89944126485233676-127.0.0.1:49508_rovu-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 620286 T1176 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> 620287 T1176 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 620287 T1176 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 620332 T1085 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/rovu,null}
[junit4:junit4] 2> 620418 T1085 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 620422 T1085 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49491 49491
[junit4:junit4] 2> 620454 T1085 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 49494
[junit4:junit4] 2> !!!! WARNING: best effort to remove /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-1372438453439 FAILED !!!!!
[junit4:junit4] 2> 620455 T1085 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 620456 T1085 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49491 49491
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=D6C4F79DCF3F97A1 -Dtests.slow=true -Dtests.locale=fr_LU -Dtests.timezone=Etc/GMT+2 -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 94.1s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:49498/rovu returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([D6C4F79DCF3F97A1:57227985B860F79D]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 620465 T1085 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 94159 T1084 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=MockRandom), _version_=PostingsFormat(name=SimpleText), n_ti=PostingsFormat(name=Memory doPackFST= false)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=fr_LU, timezone=Etc/GMT+2
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=49230864,total=134307840
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TimeZoneUtilsTest, TestWriterPerf, TestClassNameShortening, TestBinaryResponseWriter, DirectUpdateHandlerTest, ZkSolrClientTest, DebugComponentTest, ShowFileRequestHandlerTest, SolrIndexSplitterTest, TestDistributedGrouping, SynonymTokenizerTest, CachingDirectoryFactoryTest, AliasIntegrationTest, MultiTermTest, HdfsRecoveryZkTest, TestSchemaSimilarityResource, TestPropInject, TestRTGBase, JSONWriterTest, TestBM25SimilarityFactory, TestElisionMultitermQuery, TestHashPartitioner, PrimitiveFieldTypeTest, DOMUtilTest, TestSolrJ, BinaryUpdateRequestHandlerTest, TestSort, CircularListTest, TestReload, TestSolrQueryParser, HdfsChaosMonkeySafeLeaderTest, TestJoin, TestSerializedLuceneMatchVersion, TestCodecSupport, DisMaxRequestHandlerTest, SimplePostToolTest, OutputWriterTest, DocumentBuilderTest, ShardRoutingTest, TestMultiCoreConfBootstrap, TestReversedWildcardFilterFactory, IndexBasedSpellCheckerTest, AlternateDirectoryTest, CoreContainerCoreInitFailuresTest, ShardSplitTest]
[junit4:junit4] Completed in 94.72s, 1 test, 1 error <<< FAILURES!
[...truncated 845 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:386: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:366: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:190: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:443: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1245: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:889: There were test failures: 312 suites, 1316 tests, 2 errors, 25 ignored (12 assumptions)
Total time: 105 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:-UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure