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/01/14 04:59:54 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 87 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/87/
Java: 64bit/jdk1.7.0 -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZkTest.testDistribSearch
Error Message:
There are still nodes recoverying - waited for 230 seconds
Stack Trace:
java.lang.AssertionError: There are still nodes recoverying - waited for 230 seconds
at __randomizedtesting.SeedInfo.seed([94EA8396AB450D0E:150C0D8EDC1A6D32]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:168)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:126)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:121)
at org.apache.solr.cloud.BasicDistributedZkTest.testCoreUnloadAndLeaders(BasicDistributedZkTest.java:586)
at org.apache.solr.cloud.BasicDistributedZkTest.doTest(BasicDistributedZkTest.java:337)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:794)
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:601)
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:722)
Build Log:
[...truncated 8842 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4] 2> 0 T1372 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 11 T1372 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-BasicDistributedZkTest-1358134568888
[junit4:junit4] 2> 13 T1372 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 14 T1373 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 17 T1373 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 17 T1373 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 17 T1373 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 18 T1373 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 19 T1373 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 115 T1372 oasc.ZkTestServer.run start zk server on port:49552
[junit4:junit4] 2> 116 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6753ce38
[junit4:junit4] 2> 117 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 118 T1378 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 118 T1378 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 119 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49553
[junit4:junit4] 2> 120 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49553
[junit4:junit4] 2> 121 T1376 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 124 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10000 with negotiated timeout 10000 for client /127.0.0.1:49553
[junit4:junit4] 2> 126 T1378 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10000, negotiated timeout = 10000
[junit4:junit4] 2> 127 T1379 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6753ce38 name:ZooKeeperConnection Watcher:127.0.0.1:49552 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 127 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 128 T1372 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 132 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c10000
[junit4:junit4] 2> 134 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c10000 closed
[junit4:junit4] 2> 137 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@2b1fc051
[junit4:junit4] 2> 139 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 139 T1380 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 140 T1379 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 141 T1380 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 141 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49553 which had sessionid 0x13c3720e7c10000
[junit4:junit4] 2> 143 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49554
[junit4:junit4] 2> 144 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49554
[junit4:junit4] 2> 146 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10001 with negotiated timeout 10000 for client /127.0.0.1:49554
[junit4:junit4] 2> 146 T1380 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10001, negotiated timeout = 10000
[junit4:junit4] 2> 146 T1381 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b1fc051 name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 147 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 148 T1372 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 155 T1372 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 161 T1372 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 165 T1372 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 170 T1372 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 175 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 183 T1372 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> 183 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 187 T1372 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> 188 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 193 T1372 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> 194 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 198 T1372 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> 199 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 210 T1372 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> 211 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 217 T1372 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> 218 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 223 T1372 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> 224 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 230 T1372 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> 231 T1372 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 237 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c10001
[junit4:junit4] 2> 238 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49554 which had sessionid 0x13c3720e7c10001
[junit4:junit4] 2> 239 T1381 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 239 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c10001 closed
[junit4:junit4] 2> 474 T1372 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 484 T1372 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49555
[junit4:junit4] 2> 485 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 486 T1372 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 486 T1372 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.BasicDistributedZkTest-controljetty-1358134569116
[junit4:junit4] 2> 487 T1372 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1358134569116/solr.xml
[junit4:junit4] 2> 487 T1372 oasc.CoreContainer.<init> New CoreContainer 913734304
[junit4:junit4] 2> 488 T1372 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.BasicDistributedZkTest-controljetty-1358134569116/'
[junit4:junit4] 2> 489 T1372 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.BasicDistributedZkTest-controljetty-1358134569116/'
[junit4:junit4] 2> 527 T1372 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 528 T1372 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 528 T1372 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 529 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 529 T1372 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 530 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 531 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 531 T1372 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 532 T1372 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 532 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 548 T1372 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 581 T1372 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49552/solr
[junit4:junit4] 2> 582 T1372 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 583 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@68ec1990
[junit4:junit4] 2> 589 T1391 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 590 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 593 T1391 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 593 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49556
[junit4:junit4] 2> 594 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49556
[junit4:junit4] 2> 596 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10002 with negotiated timeout 20000 for client /127.0.0.1:49556
[junit4:junit4] 2> 596 T1391 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10002, negotiated timeout = 20000
[junit4:junit4] 2> 597 T1392 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68ec1990 name:ZooKeeperConnection Watcher:127.0.0.1:49552 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 598 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 604 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c10002
[junit4:junit4] 2> 605 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49556 which had sessionid 0x13c3720e7c10002
[junit4:junit4] 2> 606 T1392 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 606 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c10002 closed
[junit4:junit4] 2> 607 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 615 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@64a1d02b
[junit4:junit4] 2> 617 T1393 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 617 T1393 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 618 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49557
[junit4:junit4] 2> 619 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49557
[junit4:junit4] 2> 620 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10003 with negotiated timeout 20000 for client /127.0.0.1:49557
[junit4:junit4] 2> 620 T1393 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10003, negotiated timeout = 20000
[junit4:junit4] 2> 618 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 621 T1394 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64a1d02b name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 622 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 627 T1372 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 631 T1372 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49555_
[junit4:junit4] 2> 632 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:delete cxid:0x7 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49555_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49555_
[junit4:junit4] 2> 633 T1372 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49555_
[junit4:junit4] 2> 640 T1372 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 650 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:delete cxid:0x15 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 651 T1372 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 656 T1372 oasc.Overseer.start Overseer (id=89006707107233795-127.0.0.1:49555_-n_0000000000) starting
[junit4:junit4] 2> 664 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x1a zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 666 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x1b zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 667 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x1c zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 669 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x1d zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 671 T1396 oasc.OverseerCollectionProcessor.run Process current queue of collection messages
[junit4:junit4] 2> 673 T1372 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 678 T1372 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 688 T1395 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 688 T1397 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.BasicDistributedZkTest-controljetty-1358134569116/collection1
[junit4:junit4] 2> 689 T1397 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 691 T1397 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 691 T1397 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 694 T1397 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.BasicDistributedZkTest-controljetty-1358134569116/collection1/'
[junit4:junit4] 2> 695 T1397 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1358134569116/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 696 T1397 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1358134569116/collection1/lib/README' to classloader
[junit4:junit4] 2> 760 T1397 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 841 T1397 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 843 T1397 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 849 T1397 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1403 T1397 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1411 T1397 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1414 T1397 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1435 T1397 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1440 T1397 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1445 T1397 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1447 T1397 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1449 T1397 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.BasicDistributedZkTest-controljetty-1358134569116/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data/
[junit4:junit4] 2> 1449 T1397 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cee667
[junit4:junit4] 2> 1450 T1397 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1466 T1397 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.BasicDistributedZkTest-1358134568887/control/data forceNew:false
[junit4:junit4] 2> 1467 T1397 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data
[junit4:junit4] 2> 1467 T1397 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data/index/
[junit4:junit4] 2> 1468 T1397 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1470 T1397 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.BasicDistributedZkTest-1358134568887/control/data/index forceNew:false
[junit4:junit4] 2> 1477 T1397 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3bacf4ab; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1477 T1397 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1478 T1397 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data/index
[junit4:junit4] 2> 1479 T1397 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 1481 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1482 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 1482 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1483 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 1483 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1484 T1397 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1484 T1397 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1485 T1397 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1485 T1397 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1486 T1397 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 1486 T1397 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 1487 T1397 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1487 T1397 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 1487 T1397 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 1488 T1397 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 1488 T1397 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1489 T1397 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1490 T1397 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1491 T1397 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1491 T1397 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1492 T1397 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1492 T1397 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1493 T1397 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1493 T1397 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1494 T1397 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 1494 T1397 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 1501 T1397 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1508 T1397 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 1509 T1397 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 1511 T1397 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data
[junit4:junit4] 2> 1515 T1397 oass.SolrIndexSearcher.<init> Opening Searcher@3ea86006 main
[junit4:junit4] 2> 1517 T1397 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1518 T1397 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1518 T1397 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 1532 T1397 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 1576 T1398 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ea86006 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1584 T1397 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1585 T1397 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1586 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 2199 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2200 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:49555_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49555"}
[junit4:junit4] 2> 2200 T1395 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2201 T1395 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2201 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 2211 T1394 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> 2592 T1397 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2592 T1397 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49555 collection:control_collection shard:shard1
[junit4:junit4] 2> 2593 T1397 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2603 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2604 T1397 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2605 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2608 T1397 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2608 T1397 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2608 T1397 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49555/collection1/
[junit4:junit4] 2> 2609 T1397 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2609 T1397 oasc.SyncStrategy.syncToMe http://127.0.0.1:49555/collection1/ has no replicas
[junit4:junit4] 2> 2609 T1397 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49555/collection1/
[junit4:junit4] 2> 2609 T1397 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2616 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3724 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3752 T1394 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> 3819 T1397 oasc.ZkController.register We are http://127.0.0.1:49555/collection1/ and leader is http://127.0.0.1:49555/collection1/
[junit4:junit4] 2> 3820 T1397 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49555
[junit4:junit4] 2> 3820 T1397 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3821 T1397 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3822 T1397 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3827 T1397 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3830 T1372 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3831 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3832 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3841 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3847 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6c0ce8ee
[junit4:junit4] 2> 3848 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3848 T1399 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3849 T1399 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 3849 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49558
[junit4:junit4] 2> 3850 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49558
[junit4:junit4] 2> 3851 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10004 with negotiated timeout 10000 for client /127.0.0.1:49558
[junit4:junit4] 2> 3851 T1399 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10004, negotiated timeout = 10000
[junit4:junit4] 2> 3852 T1400 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c0ce8ee name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3852 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3853 T1372 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3857 T1372 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4023 T1372 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4028 T1372 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49559
[junit4:junit4] 2> 4028 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4029 T1372 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4030 T1372 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.BasicDistributedZkTest-jetty1-1358134572733
[junit4:junit4] 2> 4030 T1372 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1358134572733/solr.xml
[junit4:junit4] 2> 4031 T1372 oasc.CoreContainer.<init> New CoreContainer 1242895387
[junit4:junit4] 2> 4031 T1372 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.BasicDistributedZkTest-jetty1-1358134572733/'
[junit4:junit4] 2> 4032 T1372 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.BasicDistributedZkTest-jetty1-1358134572733/'
[junit4:junit4] 2> 4067 T1372 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 4068 T1372 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4069 T1372 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4069 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4070 T1372 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4070 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4071 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4071 T1372 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4072 T1372 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4072 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4086 T1372 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4104 T1372 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49552/solr
[junit4:junit4] 2> 4105 T1372 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4106 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@10a72ff3
[junit4:junit4] 2> 4107 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4107 T1410 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4109 T1410 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 4109 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49560
[junit4:junit4] 2> 4109 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49560
[junit4:junit4] 2> 4566 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10005 with negotiated timeout 20000 for client /127.0.0.1:49560
[junit4:junit4] 2> 4567 T1410 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10005, negotiated timeout = 20000
[junit4:junit4] 2> 4567 T1411 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10a72ff3 name:ZooKeeperConnection Watcher:127.0.0.1:49552 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4567 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4571 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c10005
[junit4:junit4] 2> 4572 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49560 which had sessionid 0x13c3720e7c10005
[junit4:junit4] 2> 4573 T1411 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4573 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c10005 closed
[junit4:junit4] 2> 4575 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 4586 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5001b139
[junit4:junit4] 2> 4588 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4589 T1412 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4591 T1412 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 4592 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49561
[junit4:junit4] 2> 4593 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49561
[junit4:junit4] 2> 4596 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10006 with negotiated timeout 20000 for client /127.0.0.1:49561
[junit4:junit4] 2> 4596 T1412 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10006, negotiated timeout = 20000
[junit4:junit4] 2> 4597 T1413 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5001b139 name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4598 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4600 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4603 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4607 T1372 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49559_
[junit4:junit4] 2> 4609 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10006 type:delete cxid:0x4 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49559_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49559_
[junit4:junit4] 2> 4611 T1372 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49559_
[junit4:junit4] 2> 4620 T1400 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4621 T1394 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4622 T1394 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> 4632 T1372 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4655 T1414 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.BasicDistributedZkTest-jetty1-1358134572733/collection1
[junit4:junit4] 2> 4656 T1414 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4659 T1414 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4659 T1414 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4664 T1414 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.BasicDistributedZkTest-jetty1-1358134572733/collection1/'
[junit4:junit4] 2> 4667 T1414 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1358134572733/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4668 T1414 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1358134572733/collection1/lib/README' to classloader
[junit4:junit4] 2> 4768 T1414 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 4821 T1414 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4822 T1414 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4830 T1414 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5270 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5271 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:49555_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49555"}
[junit4:junit4] 2> 5277 T1394 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> 5278 T1413 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> 5279 T1400 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> 5368 T1414 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5376 T1414 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5379 T1414 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5400 T1414 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5406 T1414 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5411 T1414 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5413 T1414 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5415 T1414 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.BasicDistributedZkTest-jetty1-1358134572733/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/
[junit4:junit4] 2> 5415 T1414 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cee667
[junit4:junit4] 2> 5416 T1414 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 5417 T1414 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.BasicDistributedZkTest-1358134568887/jetty1 forceNew:false
[junit4:junit4] 2> 5417 T1414 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1
[junit4:junit4] 2> 5417 T1414 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index/
[junit4:junit4] 2> 5418 T1414 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5419 T1414 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.BasicDistributedZkTest-1358134568887/jetty1/index forceNew:false
[junit4:junit4] 2> 5424 T1414 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@332a3b24; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5425 T1414 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5426 T1414 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index
[junit4:junit4] 2> 5426 T1414 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 5429 T1414 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5430 T1414 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 5430 T1414 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5430 T1414 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 5431 T1414 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5432 T1414 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5433 T1414 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5434 T1414 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5434 T1414 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5435 T1414 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 5436 T1414 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 5436 T1414 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5437 T1414 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 5437 T1414 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 5438 T1414 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 5439 T1414 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5440 T1414 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5440 T1414 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5441 T1414 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5442 T1414 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5443 T1414 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5443 T1414 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5444 T1414 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5445 T1414 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5446 T1414 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 5446 T1414 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 5453 T1414 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5456 T1414 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 5458 T1414 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 5460 T1414 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1
[junit4:junit4] 2> 5462 T1414 oass.SolrIndexSearcher.<init> Opening Searcher@3ddc6fdb main
[junit4:junit4] 2> 5463 T1414 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5463 T1414 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5464 T1414 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 5470 T1414 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 5509 T1415 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ddc6fdb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5519 T1414 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5519 T1414 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6790 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6791 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49559_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49559"}
[junit4:junit4] 2> 6791 T1395 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 6792 T1395 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6798 T1400 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> 6798 T1394 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> 6799 T1413 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> 7524 T1414 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7525 T1414 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49559 collection:collection1 shard:shard1
[junit4:junit4] 2> 7528 T1414 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7551 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10006 type:delete cxid:0x45 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7552 T1414 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7553 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10006 type:create cxid:0x46 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7558 T1414 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7559 T1414 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7560 T1414 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49559/collection1/
[junit4:junit4] 2> 7560 T1414 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7561 T1414 oasc.SyncStrategy.syncToMe http://127.0.0.1:49559/collection1/ has no replicas
[junit4:junit4] 2> 7562 T1414 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49559/collection1/
[junit4:junit4] 2> 7563 T1414 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7580 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10006 type:create cxid:0x50 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8312 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8325 T1413 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> 8325 T1400 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> 8325 T1394 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> 8375 T1414 oasc.ZkController.register We are http://127.0.0.1:49559/collection1/ and leader is http://127.0.0.1:49559/collection1/
[junit4:junit4] 2> 8375 T1414 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49559
[junit4:junit4] 2> 8375 T1414 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8375 T1414 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8375 T1414 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8378 T1414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8380 T1372 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8380 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8381 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8567 T1372 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8573 T1372 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49562
[junit4:junit4] 2> 8574 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8575 T1372 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8575 T1372 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.BasicDistributedZkTest-jetty2-1358134577263
[junit4:junit4] 2> 8576 T1372 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1358134577263/solr.xml
[junit4:junit4] 2> 8577 T1372 oasc.CoreContainer.<init> New CoreContainer 544904992
[junit4:junit4] 2> 8577 T1372 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.BasicDistributedZkTest-jetty2-1358134577263/'
[junit4:junit4] 2> 8578 T1372 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.BasicDistributedZkTest-jetty2-1358134577263/'
[junit4:junit4] 2> 8617 T1372 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 8618 T1372 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8619 T1372 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8620 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8620 T1372 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8621 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8622 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8622 T1372 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8623 T1372 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8623 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8639 T1372 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8660 T1372 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49552/solr
[junit4:junit4] 2> 8660 T1372 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8661 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@c432afc
[junit4:junit4] 2> 8662 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8663 T1425 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8665 T1425 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 8665 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49563
[junit4:junit4] 2> 8666 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49563
[junit4:junit4] 2> 8667 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10007 with negotiated timeout 20000 for client /127.0.0.1:49563
[junit4:junit4] 2> 8668 T1425 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10007, negotiated timeout = 20000
[junit4:junit4] 2> 8669 T1426 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c432afc name:ZooKeeperConnection Watcher:127.0.0.1:49552 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8669 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8671 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c10007
[junit4:junit4] 2> 8672 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49563 which had sessionid 0x13c3720e7c10007
[junit4:junit4] 2> 8672 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c10007 closed
[junit4:junit4] 2> 8673 T1426 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8673 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 8682 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1bc3063e
[junit4:junit4] 2> 8684 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8684 T1427 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8685 T1427 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 8686 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49564
[junit4:junit4] 2> 8687 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49564
[junit4:junit4] 2> 8688 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10008 with negotiated timeout 20000 for client /127.0.0.1:49564
[junit4:junit4] 2> 8688 T1427 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10008, negotiated timeout = 20000
[junit4:junit4] 2> 8689 T1428 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bc3063e name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8689 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8690 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8692 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8694 T1372 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49562_
[junit4:junit4] 2> 8695 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10008 type:delete cxid:0x4 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49562_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49562_
[junit4:junit4] 2> 8696 T1372 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49562_
[junit4:junit4] 2> 8700 T1400 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> 8702 T1394 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 8702 T1394 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> 8702 T1413 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 8703 T1413 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> 8705 T1400 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 8710 T1372 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 8720 T1429 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.BasicDistributedZkTest-jetty2-1358134577263/collection1
[junit4:junit4] 2> 8720 T1429 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 8721 T1429 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 8721 T1429 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 8723 T1429 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.BasicDistributedZkTest-jetty2-1358134577263/collection1/'
[junit4:junit4] 2> 8724 T1429 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1358134577263/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 8725 T1429 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1358134577263/collection1/lib/README' to classloader
[junit4:junit4] 2> 8776 T1429 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 8845 T1429 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 8847 T1429 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 8853 T1429 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 8962 T719 oasc.OverseerCollectionProcessor.run WARNING Overseer cannot talk to ZK
[junit4:junit4] 2> 9476 T1429 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9487 T1429 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9491 T1429 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9514 T1429 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9520 T1429 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9528 T1429 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9531 T1429 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9534 T1429 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.BasicDistributedZkTest-jetty2-1358134577263/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/
[junit4:junit4] 2> 9534 T1429 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cee667
[junit4:junit4] 2> 9535 T1429 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 9537 T1429 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.BasicDistributedZkTest-1358134568887/jetty2 forceNew:false
[junit4:junit4] 2> 9537 T1429 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2
[junit4:junit4] 2> 9538 T1429 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index/
[junit4:junit4] 2> 9539 T1429 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9540 T1429 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.BasicDistributedZkTest-1358134568887/jetty2/index forceNew:false
[junit4:junit4] 2> 9545 T1429 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@295da80f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9546 T1429 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9547 T1429 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index
[junit4:junit4] 2> 9547 T1429 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 9550 T1429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9551 T1429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 9551 T1429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9551 T1429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 9552 T1429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9553 T1429 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9553 T1429 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9554 T1429 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9555 T1429 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9556 T1429 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 9557 T1429 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 9557 T1429 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9558 T1429 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 9558 T1429 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 9559 T1429 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 9559 T1429 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9560 T1429 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9561 T1429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9562 T1429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9562 T1429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9563 T1429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9564 T1429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9564 T1429 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9566 T1429 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 9566 T1429 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 9567 T1429 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 9572 T1429 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9574 T1429 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 9575 T1429 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 9578 T1429 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2
[junit4:junit4] 2> 9580 T1429 oass.SolrIndexSearcher.<init> Opening Searcher@782dadad main
[junit4:junit4] 2> 9581 T1429 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9581 T1429 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9582 T1429 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 9612 T1429 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 9647 T1430 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@782dadad main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9655 T1429 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9655 T1429 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 9837 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9838 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49559_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49559"}
[junit4:junit4] 2> 9845 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49562_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49562"}
[junit4:junit4] 2> 9845 T1395 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 9845 T1395 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 9852 T1400 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> 9852 T1428 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> 9853 T1413 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> 9853 T1394 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> 10658 T1429 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 10658 T1429 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49562 collection:collection1 shard:shard2
[junit4:junit4] 2> 10660 T1429 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 10669 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10008 type:delete cxid:0x42 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4] 2> 10671 T1429 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 10671 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10008 type:create cxid:0x43 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 10674 T1429 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 10674 T1429 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 10674 T1429 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49562/collection1/
[junit4:junit4] 2> 10675 T1429 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 10675 T1429 oasc.SyncStrategy.syncToMe http://127.0.0.1:49562/collection1/ has no replicas
[junit4:junit4] 2> 10675 T1429 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49562/collection1/
[junit4:junit4] 2> 10676 T1429 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 10681 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c10008 type:create cxid:0x4c zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11365 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11379 T1394 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> 11379 T1413 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> 11379 T1400 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> 11379 T1428 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> 11400 T1429 oasc.ZkController.register We are http://127.0.0.1:49562/collection1/ and leader is http://127.0.0.1:49562/collection1/
[junit4:junit4] 2> 11401 T1429 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49562
[junit4:junit4] 2> 11402 T1429 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 11402 T1429 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 11407 T1429 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11409 T1429 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11410 T1372 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11410 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11411 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11623 T1372 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11627 T1372 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49565
[junit4:junit4] 2> 11628 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11629 T1372 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11629 T1372 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.BasicDistributedZkTest-jetty3-1358134580300
[junit4:junit4] 2> 11630 T1372 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1358134580300/solr.xml
[junit4:junit4] 2> 11630 T1372 oasc.CoreContainer.<init> New CoreContainer 1802819603
[junit4:junit4] 2> 11631 T1372 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.BasicDistributedZkTest-jetty3-1358134580300/'
[junit4:junit4] 2> 11631 T1372 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.BasicDistributedZkTest-jetty3-1358134580300/'
[junit4:junit4] 2> 11665 T1372 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 11666 T1372 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11666 T1372 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11667 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11667 T1372 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11668 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11668 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11669 T1372 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11670 T1372 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11670 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11685 T1372 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11703 T1372 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49552/solr
[junit4:junit4] 2> 11704 T1372 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11705 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@126f0ec
[junit4:junit4] 2> 11706 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11707 T1440 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 11709 T1440 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 11709 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49566
[junit4:junit4] 2> 11709 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49566
[junit4:junit4] 2> 13074 T1376 oazsp.FileTxnLog.commit WARNING fsync-ing the write ahead log in SyncThread:0 took 1364ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide
[junit4:junit4] 2> 13075 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c10009 with negotiated timeout 20000 for client /127.0.0.1:49566
[junit4:junit4] 2> 13075 T1440 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c10009, negotiated timeout = 20000
[junit4:junit4] 2> 13076 T1441 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@126f0ec name:ZooKeeperConnection Watcher:127.0.0.1:49552 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13076 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13078 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13078 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c10009
[junit4:junit4] 2> 13079 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49566 which had sessionid 0x13c3720e7c10009
[junit4:junit4] 2> 13079 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49562_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49562"}
[junit4:junit4] 2> 13080 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c10009 closed
[junit4:junit4] 2> 13080 T1441 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 13080 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 13086 T1428 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> 13088 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ee4486b
[junit4:junit4] 2> 13089 T1394 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> 13089 T1413 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> 13089 T1400 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> 13090 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13090 T1442 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13091 T1442 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 13091 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49567
[junit4:junit4] 2> 13092 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49567
[junit4:junit4] 2> 13094 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c1000a with negotiated timeout 20000 for client /127.0.0.1:49567
[junit4:junit4] 2> 13094 T1442 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c1000a, negotiated timeout = 20000
[junit4:junit4] 2> 13094 T1443 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ee4486b name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13095 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13096 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c1000a type:create cxid:0x1 zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13097 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c1000a type:create cxid:0x2 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13099 T1372 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49565_
[junit4:junit4] 2> 13100 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c1000a type:delete cxid:0x4 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49565_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49565_
[junit4:junit4] 2> 13101 T1372 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49565_
[junit4:junit4] 2> 13104 T1400 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> 13105 T1428 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> 13106 T1394 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13106 T1394 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> 13107 T1413 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13107 T1413 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> 13109 T1428 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13110 T1400 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13113 T1372 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 13121 T1444 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.BasicDistributedZkTest-jetty3-1358134580300/collection1
[junit4:junit4] 2> 13121 T1444 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 13123 T1444 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 13123 T1444 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 13125 T1444 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.BasicDistributedZkTest-jetty3-1358134580300/collection1/'
[junit4:junit4] 2> 13126 T1444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1358134580300/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 13126 T1444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1358134580300/collection1/lib/README' to classloader
[junit4:junit4] 2> 13174 T1444 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 13237 T1444 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13239 T1444 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13244 T1444 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13819 T1444 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13828 T1444 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13832 T1444 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13853 T1444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13859 T1444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13864 T1444 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13866 T1444 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13868 T1444 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.BasicDistributedZkTest-jetty3-1358134580300/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/
[junit4:junit4] 2> 13868 T1444 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cee667
[junit4:junit4] 2> 13869 T1444 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 13870 T1444 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.BasicDistributedZkTest-1358134568887/jetty3 forceNew:false
[junit4:junit4] 2> 13870 T1444 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 13871 T1444 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index/
[junit4:junit4] 2> 13871 T1444 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13872 T1444 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.BasicDistributedZkTest-1358134568887/jetty3/index forceNew:false
[junit4:junit4] 2> 13880 T1444 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f7e0e05; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13881 T1444 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13882 T1444 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index
[junit4:junit4] 2> 13883 T1444 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 13887 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13888 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 13889 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13889 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 13890 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13891 T1444 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13892 T1444 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13893 T1444 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13894 T1444 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13895 T1444 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 13897 T1444 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 13898 T1444 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13899 T1444 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 13900 T1444 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 13900 T1444 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 13902 T1444 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13903 T1444 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13904 T1444 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13905 T1444 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13906 T1444 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13907 T1444 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13908 T1444 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13909 T1444 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13910 T1444 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13911 T1444 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 13912 T1444 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 13921 T1444 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13924 T1444 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 13926 T1444 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 13928 T1444 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 13930 T1444 oass.SolrIndexSearcher.<init> Opening Searcher@15702e7f main
[junit4:junit4] 2> 13931 T1444 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13931 T1444 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13932 T1444 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 13938 T1444 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 13970 T1445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15702e7f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13978 T1444 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13979 T1444 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14599 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14600 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49565_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49565"}
[junit4:junit4] 2> 14601 T1395 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 14601 T1395 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 14608 T1443 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> 14608 T1400 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> 14608 T1394 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> 14608 T1413 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> 14609 T1428 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> 14982 T1444 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 14983 T1444 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49565 collection:collection1 shard:shard1
[junit4:junit4] 2> 14987 T1444 oasc.ZkController.register We are http://127.0.0.1:49565/collection1/ and leader is http://127.0.0.1:49559/collection1/
[junit4:junit4] 2> 14988 T1444 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49565
[junit4:junit4] 2> 14988 T1444 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 14988 T1444 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C76 name=collection1 org.apache.solr.core.SolrCore@67493272 url=http://127.0.0.1:49565/collection1 node=127.0.0.1:49565_ C76_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49565_, base_url=http://127.0.0.1:49565}
[junit4:junit4] 2> 14989 T1446 C76 P49565 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 14990 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 14990 T1444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14991 T1446 C76 P49565 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 14991 T1446 C76 P49565 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14992 T1372 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 14993 T1446 C76 P49565 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14993 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 14993 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15195 T1372 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 15199 T1372 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49569
[junit4:junit4] 2> 15200 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 15201 T1372 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 15201 T1372 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.BasicDistributedZkTest-jetty4-1358134583879
[junit4:junit4] 2> 15202 T1372 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1358134583879/solr.xml
[junit4:junit4] 2> 15202 T1372 oasc.CoreContainer.<init> New CoreContainer 505531063
[junit4:junit4] 2> 15203 T1372 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.BasicDistributedZkTest-jetty4-1358134583879/'
[junit4:junit4] 2> 15204 T1372 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.BasicDistributedZkTest-jetty4-1358134583879/'
[junit4:junit4] 2> 15242 T1372 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 15243 T1372 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 15243 T1372 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 15244 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 15244 T1372 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 15245 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 15245 T1372 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 15246 T1372 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 15247 T1372 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 15247 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 15262 T1372 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 15280 T1372 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49552/solr
[junit4:junit4] 2> 15281 T1372 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 15282 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@21164eff
[junit4:junit4] 2> 15283 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15283 T1456 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 15285 T1456 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 15285 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49570
[junit4:junit4] 2> 15285 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49570
[junit4:junit4] 2> 15287 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c1000b with negotiated timeout 20000 for client /127.0.0.1:49570
[junit4:junit4] 2> 15287 T1456 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c1000b, negotiated timeout = 20000
[junit4:junit4] 2> 15287 T1457 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21164eff name:ZooKeeperConnection Watcher:127.0.0.1:49552 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15288 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15289 T1377 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c3720e7c1000b
[junit4:junit4] 2> 15291 T1374 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49570 which had sessionid 0x13c3720e7c1000b
[junit4:junit4] 2> 15291 T1372 oaz.ZooKeeper.close Session: 0x13c3720e7c1000b closed
[junit4:junit4] 2> 15291 T1457 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 15291 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 15298 T1372 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49552/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@9c0b0ed
[junit4:junit4] 2> 15299 T1372 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15299 T1458 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49552. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 15300 T1458 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49552, initiating session
[junit4:junit4] 2> 15300 T1374 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49571
[junit4:junit4] 2> 15301 T1374 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49571
[junit4:junit4] 2> 15302 T1376 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c3720e7c1000c with negotiated timeout 20000 for client /127.0.0.1:49571
[junit4:junit4] 2> 15303 T1458 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49552, sessionid = 0x13c3720e7c1000c, negotiated timeout = 20000
[junit4:junit4] 2> 15303 T1459 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9c0b0ed name:ZooKeeperConnection Watcher:127.0.0.1:49552/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15303 T1372 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15304 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c1000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15306 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c1000c type:create cxid:0x2 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15307 T1372 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49569_
[junit4:junit4] 2> 15308 T1377 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c3720e7c1000c type:delete cxid:0x4 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49569_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49569_
[junit4:junit4] 2> 15309 T1372 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49569_
[junit4:junit4] 2> 15313 T1400 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> 15313 T1443 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> 15313 T1428 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> 15315 T1394 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15315 T1394 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> 15316 T1413 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15316 T1413 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> 15319 T1428 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15320 T1443 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15320 T1400 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15324 T1372 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 15332 T1460 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.BasicDistributedZkTest-jetty4-1358134583879/collection1
[junit4:junit4] 2> 15332 T1460 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 15333 T1460 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 15334 T1460 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 15336 T1460 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.BasicDistributedZkTest-jetty4-1358134583879/collection1/'
[junit4:junit4] 2> 15337 T1460 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1358134583879/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 15337 T1460 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1358134583879/collection1/lib/README' to classloader
[junit4:junit4] 2> 15385 T1460 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 15447 T1460 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 15449 T1460 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 15454 T1460 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 16060 T1460 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 16071 T1460 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 16075 T1460 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 16096 T1460 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 16101 T1460 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 16107 T1460 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 16108 T1460 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 16110 T1460 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.BasicDistributedZkTest-jetty4-1358134583879/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/
[junit4:junit4] 2> 16111 T1460 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cee667
[junit4:junit4] 2> 16111 T1460 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 16112 T1460 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.BasicDistributedZkTest-1358134568887/jetty4 forceNew:false
[junit4:junit4] 2> 16113 T1460 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 16113 T1460 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index/
[junit4:junit4] 2> 16113 T1460 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 16114 T1460 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.BasicDistributedZkTest-1358134568887/jetty4/index forceNew:false
[junit4:junit4] 2> 16117 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16119 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49565_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49565"}
[junit4:junit4] 2> 16121 T1460 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@31960793; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 16122 T1460 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 16123 T1460 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index
[junit4:junit4] 2> 16124 T1460 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 16126 T1394 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> 16129 T1460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 16129 T1460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 16130 T1460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 16130 T1460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 16131 T1460 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 16131 T1460 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 16132 T1460 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 16133 T1460 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 16134 T1459 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> 16135 T1428 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> 16136 T1460 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 16137 T1460 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 16138 T1460 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 16138 T1460 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 16139 T1460 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 16139 T1460 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 16140 T1460 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 16140 T1460 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 16141 T1460 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16142 T1460 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16143 T1460 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16143 T1460 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16144 T1460 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16144 T1400 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> 16145 T1460 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16146 T1460 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16146 T1460 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 16147 T1460 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 16148 T1460 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 16155 T1443 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> 16155 T1413 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> 16156 T1460 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 16159 T1460 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 16163 T1460 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 16166 T1460 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 16169 T1460 oass.SolrIndexSearcher.<init> Opening Searcher@b4559bf main
[junit4:junit4] 2> 16170 T1460 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 16171 T1460 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 16171 T1460 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 16178 T1460 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 16211 T1461 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b4559bf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 16220 T1460 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 16220 T1460 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 17675 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17676 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49569_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49569"}
[junit4:junit4] 2> 17676 T1395 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 17676 T1395 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 17683 T1443 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> 17683 T1400 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> 17683 T1394 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> 17683 T1459 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> 17683 T1428 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> 17683 T1413 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> 18225 T1460 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 18226 T1460 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49569 collection:collection1 shard:shard2
[junit4:junit4] 2> 18237 T1460 oasc.ZkController.register We are http://127.0.0.1:49569/collection1/ and leader is http://127.0.0.1:49562/collection1/
[junit4:junit4] 2> 18238 T1460 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49569
[junit4:junit4] 2> 18238 T1460 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 18239 T1460 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C77 name=collection1 org.apache.solr.core.SolrCore@196bbd4c url=http://127.0.0.1:49569/collection1 node=127.0.0.1:49569_ C77_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49569_, base_url=http://127.0.0.1:49569}
[junit4:junit4] 2> 18240 T1462 C77 P49569 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 18243 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 18243 T1462 C77 P49569 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 18243 T1460 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18244 T1462 C77 P49569 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18248 T1462 C77 P49569 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18247 T1372 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 18250 T1372 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 18252 T1372 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18259 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18261 T1372 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 18262 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C76_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49565_, base_url=http://127.0.0.1:49565}
[junit4:junit4] 2> 19010 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49559/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 19011 T1446 C76 P49565 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49565 START replicas=[http://127.0.0.1:49559/collection1/] nUpdates=100
[junit4:junit4] 2> 19012 T1446 C76 P49565 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 19014 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 19014 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 19015 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 19016 T1446 C76 P49565 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 19016 T1446 C76 P49565 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49559/collection1/. core=collection1
[junit4:junit4] 2> 19017 T1446 C76 P49565 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C78 name=collection1 org.apache.solr.core.SolrCore@52d0be54 url=http://127.0.0.1:49559/collection1 node=127.0.0.1:49559_ C78_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49559_, base_url=http://127.0.0.1:49559, leader=true}
[junit4:junit4] 2> 19032 T1407 C78 P49559 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 19037 T1406 C78 P49559 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 19039 T1406 C78 P49559 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1
[junit4:junit4] 2> 19042 T1406 C78 P49559 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@332a3b24; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 19043 T1406 C78 P49559 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 19046 T1406 C78 P49559 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@332a3b24; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@332a3b24; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19047 T1406 C78 P49559 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19049 T1406 C78 P49559 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1
[junit4:junit4] 2> 19049 T1406 C78 P49559 oass.SolrIndexSearcher.<init> Opening Searcher@f432d21 realtime
[junit4:junit4] 2> 19050 T1406 C78 P49559 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19050 T1406 C78 P49559 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 19053 T1446 C76 P49565 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19053 T1446 C76 P49565 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 19057 T1404 C78 P49559 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19058 T1404 C78 P49559 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 19059 T1446 C76 P49565 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 19060 T1446 C76 P49565 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 19060 T1446 C76 P49565 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 19063 T1405 C78 P49559 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1
[junit4:junit4] 2> 19064 T1405 C78 P49559 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1/index
[junit4:junit4] 2> 19064 T1405 C78 P49559 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 19065 T1446 C76 P49565 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 19066 T1446 C76 P49565 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.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942 forceNew:false
[junit4:junit4] 2> 19067 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19068 T1446 C76 P49565 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e857433; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 19073 T1407 C78 P49559 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 19076 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index
[junit4:junit4] 2> 19076 T1446 C76 P49565 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 19077 T1446 C76 P49565 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130114043627942
[junit4:junit4] 2> 19078 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19079 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19079 T1446 C76 P49565 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942
[junit4:junit4] 2> 19082 T1446 C76 P49565 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e857433; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19083 T1446 C76 P49565 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19085 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19085 T1446 C76 P49565 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 19085 T1446 C76 P49565 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 19086 T1446 C76 P49565 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 19086 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942
[junit4:junit4] 2> 19087 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19090 T1446 C76 P49565 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e857433; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19091 T1446 C76 P49565 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19091 T1446 C76 P49565 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 19092 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19092 T1446 C76 P49565 oass.SolrIndexSearcher.<init> Opening Searcher@3300811b main
[junit4:junit4] 2> 19094 T1445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3300811b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 19095 T1445 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index
[junit4:junit4] 2> 19096 T1446 C76 P49565 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 19098 T1446 C76 P49565 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e857433; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e857433; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 19098 T1446 C76 P49565 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 19099 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 19100 T1446 C76 P49565 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19100 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index.20130114043627942
[junit4:junit4] 2> 19100 T1446 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3/index
[junit4:junit4] 2> 19100 T1446 C76 P49565 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 19101 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 19101 T1446 C76 P49565 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 19101 T1446 C76 P49565 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19103 T1446 C76 P49565 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 19194 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19195 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49569_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49569"}
[junit4:junit4] 2> 19201 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49565_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49565"}
[junit4:junit4] 2> 19210 T1443 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> 19210 T1400 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> 19210 T1428 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> 19210 T1459 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> 19210 T1394 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> 19210 T1413 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> 19269 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20276 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C77_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49569_, base_url=http://127.0.0.1:49569}
[junit4:junit4] 2> 21270 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49562/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 21270 T1462 C77 P49569 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49569 START replicas=[http://127.0.0.1:49562/collection1/] nUpdates=100
[junit4:junit4] 2> 21271 T1462 C77 P49569 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 21271 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 21271 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 21272 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 21272 T1462 C77 P49569 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 21272 T1462 C77 P49569 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49562/collection1/. core=collection1
[junit4:junit4] 2> 21273 T1462 C77 P49569 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C79 name=collection1 org.apache.solr.core.SolrCore@4a20c70e url=http://127.0.0.1:49562/collection1 node=127.0.0.1:49562_ C79_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49562_, base_url=http://127.0.0.1:49562, leader=true}
[junit4:junit4] 2> 21281 T1419 C79 P49562 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 21284 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21284 T1423 C79 P49562 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 21286 T1423 C79 P49562 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2
[junit4:junit4] 2> 21290 T1423 C79 P49562 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@295da80f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 21291 T1423 C79 P49562 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 21295 T1423 C79 P49562 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@295da80f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@295da80f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 21295 T1423 C79 P49562 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 21296 T1423 C79 P49562 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2
[junit4:junit4] 2> 21297 T1423 C79 P49562 oass.SolrIndexSearcher.<init> Opening Searcher@7e0a296 realtime
[junit4:junit4] 2> 21297 T1423 C79 P49562 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21298 T1423 C79 P49562 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 21300 T1462 C77 P49569 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21300 T1462 C77 P49569 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 21303 T1420 C79 P49562 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21304 T1420 C79 P49562 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 21305 T1462 C77 P49569 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 21305 T1462 C77 P49569 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 21305 T1462 C77 P49569 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 21309 T1421 C79 P49562 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2
[junit4:junit4] 2> 21310 T1421 C79 P49562 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2/index
[junit4:junit4] 2> 21310 T1421 C79 P49562 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 21311 T1462 C77 P49569 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 21312 T1462 C77 P49569 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.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188 forceNew:false
[junit4:junit4] 2> 21313 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21314 T1462 C77 P49569 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d513706; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 21318 T1419 C79 P49562 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 21320 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index
[junit4:junit4] 2> 21321 T1462 C77 P49569 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 21321 T1462 C77 P49569 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130114043630188
[junit4:junit4] 2> 21322 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21323 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21323 T1462 C77 P49569 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188
[junit4:junit4] 2> 21326 T1462 C77 P49569 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d513706; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 21327 T1462 C77 P49569 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 21328 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21328 T1462 C77 P49569 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 21329 T1462 C77 P49569 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 21329 T1462 C77 P49569 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 21330 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188
[junit4:junit4] 2> 21330 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21333 T1462 C77 P49569 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d513706; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 21333 T1462 C77 P49569 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 21334 T1462 C77 P49569 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 21334 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21335 T1462 C77 P49569 oass.SolrIndexSearcher.<init> Opening Searcher@1aea6837 main
[junit4:junit4] 2> 21337 T1461 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1aea6837 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 21337 T1461 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index
[junit4:junit4] 2> 21338 T1462 C77 P49569 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 21340 T1462 C77 P49569 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d513706; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d513706; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 21341 T1462 C77 P49569 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 21341 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 21342 T1462 C77 P49569 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21342 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index.20130114043630188
[junit4:junit4] 2> 21342 T1462 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4/index
[junit4:junit4] 2> 21343 T1462 C77 P49569 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 21343 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 21343 T1462 C77 P49569 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 21343 T1462 C77 P49569 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21345 T1462 C77 P49569 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 22231 T1395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22232 T1395 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:49569_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49569"}
[junit4:junit4] 2> 22239 T1400 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> 22239 T1394 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> 22240 T1459 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> 22240 T1428 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> 22239 T1443 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> 22239 T1413 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> 22289 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22291 T1372 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C80 name=collection1 org.apache.solr.core.SolrCore@3911d92e url=http://127.0.0.1:49555/collection1 node=127.0.0.1:49555_ C80_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49555_, base_url=http://127.0.0.1:49555, leader=true}
[junit4:junit4] 2> 22302 T1390 C80 P49555 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data
[junit4:junit4] 2> 22305 T1390 C80 P49555 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3bacf4ab; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22306 T1390 C80 P49555 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22307 T1390 C80 P49555 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/control/data
[junit4:junit4] 2> 22308 T1390 C80 P49555 oass.SolrIndexSearcher.<init> Opening Searcher@2f1b04ed realtime
[junit4:junit4] 2> 22309 T1390 C80 P49555 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1424107337076965376)} 0 9
[junit4:junit4] 2> 22314 T1424 C79 P49562 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty2
[junit4:junit4] 2> 22322 T1409 C78 P49559 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty1
[junit4:junit4] 2> C77_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49569_, base_url=http://127.0.0.1:49569}
[junit4:junit4] 2> 22331 T1455 C77 P49569 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty4
[junit4:junit4] 2> 22333 T1455 C77 P49569 /update {update.distrib=FROMLEADER&_version_=-1424107337089548288&update.from=http://127.0.0.1:49562/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1424107337089548288)} 0 4
[junit4:junit4] 2> C76_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49565_, base_url=http://127.0.0.1:49565}
[junit4:junit4] 2> 22337 T1435 C76 P49565 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1358134568887/jetty3
[junit4:junit4] 2> 22338 T1435 C76 P49565 /update {update.distrib=FROMLEADER&_version_=-1424107337097936896&update.from=http://127.0.0.1:49559/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1424107337097936896)} 0 3
[junit4:junit4] 2> 22339 T1409 C78 P49559 /update {update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1424107337097936896)} 0 19
[junit4:junit4] 2> 22340 T1424 C79 P49562 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1424107337089548288)} 0 28
[junit4:junit4] 2> 22350 T1385 C80 P49555 /update {wt=javabin&version=2} {add=[1 (1424107337124151296)]} 0 5
[junit4:junit4] 2> 22372 T1436 C76 P49565 /update {distrib.from=http://127.0.0.1:49559/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1424107337135685632)]} 0 4
[junit4:junit4] 2> 22373 T1404 C78 P49559 /update {distrib.from=http://127.0.0.1:49562/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1424107337135685632)]} 0 17
[junit4:junit4] 2> 22374 T1420 C79 P49562 /update {wt=javabin&version=2} {add=[1]} 0 21
[junit4:junit4] 2> 22380 T1386 C80 P49555 /update {wt=javabin&version=2} {add=[2 (1424107337158754304)]} 0 3
[junit4:junit4] 2> 22397 T1450 C77 P49569 /update {distrib.from=http://127.0.0.1:49562/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1424107337166094336)]} 0 5
[junit4:junit4] 2> 22398 T1421 C79 P49562 /update {distrib.f
[...truncated too long message...]
org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:121)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZkTest.testCoreUnloadAndLeaders(BasicDistributedZkTest.java:586)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZkTest.doTest(BasicDistributedZkTest.java:337)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:794)
[junit4:junit4] > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4] > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4] > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4] > at java.lang.reflect.Method.invoke(Method.java:601)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] > at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4] > at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4] > at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] > at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] > at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] > at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] > at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] > at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 390576 T1372 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41: {n_f1=PostingsFormat(name=MockRandom), foo_b=MockVariableIntBlock(baseBlockSize=118), cat=PostingsFormat(name=Lucene41WithOrds), foo_d=PostingsFormat(name=SimpleText), foo_f=MockVariableIntBlock(baseBlockSize=118), n_tl1=PostingsFormat(name=MockRandom), n_d1=PostingsFormat(name=Lucene41WithOrds), rnd_b=PostingsFormat(name=SimpleText), intDefault=PostingsFormat(name=MockRandom), n_td1=PostingsFormat(name=MockRandom), timestamp=PostingsFormat(name=Lucene41WithOrds), id=PostingsFormat(name=SimpleText), range_facet_sl=PostingsFormat(name=SimpleText), range_facet_si=PostingsFormat(name=Lucene41WithOrds), oddField_s=PostingsFormat(name=SimpleText), sequence_i=PostingsFormat(name=SimpleText), name=PostingsFormat(name=SimpleText), foo_i=PostingsFormat(name=MockRandom), regex_dup_B_s=PostingsFormat(name=Lucene41WithOrds), multiDefault=PostingsFormat(name=Lucene41WithOrds), n_tf1=PostingsFormat(name=Lucene41WithOrds), n_dt1=PostingsFormat(name=MockRandom), genre_s=PostingsFormat(name=SimpleText), author_t=PostingsFormat(name=MockRandom), n_ti1=PostingsFormat(name=SimpleText), range_facet_l=PostingsFormat(name=Lucene41WithOrds), text=MockVariableIntBlock(baseBlockSize=118), _version_=PostingsFormat(name=MockRandom), val_i=PostingsFormat(name=SimpleText), SubjectTerms_mfacet=PostingsFormat(name=MockRandom), series_t=PostingsFormat(name=MockRandom), a_t=PostingsFormat(name=Lucene41WithOrds), n_tdt1=PostingsFormat(name=MockRandom), regex_dup_A_s=MockVariableIntBlock(baseBlockSize=118), price=MockVariableIntBlock(baseBlockSize=118), other_tl1=PostingsFormat(name=MockRandom), n_l1=PostingsFormat(name=Lucene41WithOrds), a_si=PostingsFormat(name=MockRandom), inStock=MockVariableIntBlock(baseBlockSize=118)}, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=ja_JP, timezone=Africa/Tunis
[junit4:junit4] 2> NOTE: Mac OS X 10.8.2 x86_64/Oracle Corporation 1.7.0_10 (64-bit)/cpus=2,threads=1,free=241743496,total=469762048
[junit4:junit4] 2> NOTE: All tests run in this JVM: [FieldAnalysisRequestHandlerTest, OverseerCollectionProcessorTest, SolrPluginUtilsTest, DirectSolrSpellCheckerTest, EchoParamsTest, TermVectorComponentDistributedTest, SimplePostToolTest, CacheHeaderTest, TestQueryUtils, ConvertedLegacyTest, TimeZoneUtilsTest, DOMUtilTest, FullSolrCloudDistribCmdsTest, TestSuggestSpellingConverter, DefaultValueUpdateProcessorTest, TestCollationField, IndexReaderFactoryTest, OverseerTest, PeerSyncTest, BasicDistributedZk2Test, TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest, SOLR749Test, NoCacheHeaderTest, SpellPossibilityIteratorTest, PrimitiveFieldTypeTest, TestQuerySenderNoQuery, ClusterStateUpdateTest, LoggingHandlerTest, PreAnalyzedFieldTest, HighlighterTest, TestStressRecovery, TestCoreContainer, OutputWriterTest, PathHierarchyTokenizerFactoryTest, BasicFunctionalityTest, XsltUpdateRequestHandlerTest, TestFunctionQuery, URLClassifyProcessorTest, SystemInfoHandlerTest, DocumentBuilderTest, MinimalSchemaTest, AutoCommitTest, ClusterStateTest, MBeansHandlerTest, QueryEqualityTest, TestValueSourceCache, TestWordDelimiterFilterFactory, LeaderElectionTest, CurrencyFieldTest, JSONWriterTest, QueryElevationComponentTest, SuggesterFSTTest, TestBinaryField, TestMergePolicyConfig, TestReload, CSVRequestHandlerTest, ShowFileRequestHandlerTest, TestCSVResponseWriter, RequiredFieldsTest, BasicDistributedZkTest]
[junit4:junit4] Completed in 390.93s, 1 test, 1 failure <<< FAILURES!
[...truncated 563 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:344: 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:178: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:428: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1176: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:841: There were test failures: 246 suites, 1029 tests, 1 failure, 14 ignored (3 assumptions)
Total time: 64 minutes 14 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.7.0 -XX:+UseG1GC
Email was triggered for: Failure
Sending email for trigger: Failure