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/02/11 08:59:10 UTC
[JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 211 -
Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/211/
Java: 64bit/jdk1.7.0 -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZkTest.testDistribSearch
Error Message:
distrib-dup-test-chain-explicit: doc#24 has wrong value for regex_dup_B_s expected:<x[_x]> but was:<x[]>
Stack Trace:
org.junit.ComparisonFailure: distrib-dup-test-chain-explicit: doc#24 has wrong value for regex_dup_B_s expected:<x[_x]> but was:<x[]>
at __randomizedtesting.SeedInfo.seed([8E9837FD386A6C8D:F7EB9E54F350CB1]:0)
at org.junit.Assert.assertEquals(Assert.java:125)
at org.apache.solr.cloud.BasicDistributedZkTest.testUpdateProcessorsRunOnlyOnce(BasicDistributedZkTest.java:904)
at org.apache.solr.cloud.BasicDistributedZkTest.doTest(BasicDistributedZkTest.java:334)
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 8834 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4] 2> 0 T1015 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 14 T1015 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-1360567249083
[junit4:junit4] 2> 15 T1015 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 16 T1016 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 18 T1016 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 18 T1016 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 18 T1016 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 19 T1016 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 20 T1015 oasc.ZkTestServer.run start zk server on port:49583
[junit4:junit4] 2> 24 T1016 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-1360567249082/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 23 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4a46d6ba
[junit4:junit4] 2> 28 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 29 T1021 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 29 T1021 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 30 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49584
[junit4:junit4] 2> 31 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49584
[junit4:junit4] 2> 31 T1019 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 45 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50000 with negotiated timeout 10000 for client /127.0.0.1:49584
[junit4:junit4] 2> 46 T1021 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50000, negotiated timeout = 10000
[junit4:junit4] 2> 55 T1022 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a46d6ba name:ZooKeeperConnection Watcher:127.0.0.1:49583 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 59 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 59 T1015 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 75 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c50000
[junit4:junit4] 2> 77 T1022 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 78 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49584 which had sessionid 0x13cc820a8c50000
[junit4:junit4] 2> 78 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c50000 closed
[junit4:junit4] 2> 80 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5889de0c
[junit4:junit4] 2> 82 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 83 T1023 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 86 T1023 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 87 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49585
[junit4:junit4] 2> 87 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49585
[junit4:junit4] 2> 89 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50001 with negotiated timeout 10000 for client /127.0.0.1:49585
[junit4:junit4] 2> 89 T1023 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50001, negotiated timeout = 10000
[junit4:junit4] 2> 90 T1024 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5889de0c name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 90 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 90 T1015 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 97 T1015 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 101 T1015 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 110 T1015 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 124 T1015 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> 125 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 134 T1015 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> 136 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 149 T1015 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> 150 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 158 T1015 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> 159 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 164 T1015 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> 164 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 169 T1015 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> 170 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 175 T1015 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> 176 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 188 T1015 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> 190 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 212 T1015 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> 213 T1015 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 217 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c50001
[junit4:junit4] 2> 218 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49585 which had sessionid 0x13cc820a8c50001
[junit4:junit4] 2> 219 T1024 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 219 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c50001 closed
[junit4:junit4] 2> 414 T1015 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 435 T1015 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49586
[junit4:junit4] 2> 436 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 437 T1015 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 437 T1015 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-1360567249288
[junit4:junit4] 2> 438 T1015 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-1360567249288/solr.xml
[junit4:junit4] 2> 438 T1015 oasc.CoreContainer.<init> New CoreContainer 1276963795
[junit4:junit4] 2> 439 T1015 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-1360567249288/'
[junit4:junit4] 2> 439 T1015 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-1360567249288/'
[junit4:junit4] 2> 481 T1015 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 481 T1015 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 482 T1015 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 482 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 483 T1015 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 483 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 484 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 484 T1015 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 485 T1015 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 485 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 499 T1015 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 516 T1015 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49583/solr
[junit4:junit4] 2> 517 T1015 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 518 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@a163ba4
[junit4:junit4] 2> 519 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 520 T1034 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 521 T1034 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 521 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49587
[junit4:junit4] 2> 522 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49587
[junit4:junit4] 2> 523 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50002 with negotiated timeout 20000 for client /127.0.0.1:49587
[junit4:junit4] 2> 524 T1034 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50002, negotiated timeout = 20000
[junit4:junit4] 2> 524 T1035 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a163ba4 name:ZooKeeperConnection Watcher:127.0.0.1:49583 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 524 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 527 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c50002
[junit4:junit4] 2> 528 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c50002 closed
[junit4:junit4] 2> 528 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 533 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2f4fe4b1
[junit4:junit4] 2> 534 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49587 which had sessionid 0x13cc820a8c50002
[junit4:junit4] 2> 535 T1035 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 535 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 536 T1036 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 537 T1036 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 538 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49588
[junit4:junit4] 2> 538 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49588
[junit4:junit4] 2> 539 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50003 with negotiated timeout 20000 for client /127.0.0.1:49588
[junit4:junit4] 2> 539 T1036 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50003, negotiated timeout = 20000
[junit4:junit4] 2> 540 T1037 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f4fe4b1 name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 541 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 548 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 553 T1015 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 557 T1015 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49586_
[junit4:junit4] 2> 558 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49586_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49586_
[junit4:junit4] 2> 559 T1015 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49586_
[junit4:junit4] 2> 565 T1015 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 572 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 574 T1015 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 578 T1015 oasc.Overseer.start Overseer (id=89166135236558851-127.0.0.1:49586_-n_0000000000) starting
[junit4:junit4] 2> 580 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 581 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 583 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 584 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 586 T1039 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 588 T1015 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 594 T1015 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 601 T1040 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-1360567249288/collection1
[junit4:junit4] 2> 601 T1040 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 602 T1038 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 603 T1040 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 603 T1040 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 606 T1040 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-1360567249288/collection1/'
[junit4:junit4] 2> 607 T1040 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-1360567249288/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 607 T1040 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-1360567249288/collection1/lib/README' to classloader
[junit4:junit4] 2> 716 T1040 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 817 T1040 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 819 T1040 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 824 T1040 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1479 T1040 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1489 T1040 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1492 T1040 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1532 T1040 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1546 T1040 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1551 T1040 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1553 T1040 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1555 T1040 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-1360567249288/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/control/data/
[junit4:junit4] 2> 1555 T1040 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@409315af
[junit4:junit4] 2> 1557 T1040 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1558 T1040 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-1360567249082/control/data forceNew:false
[junit4:junit4] 2> 1558 T1040 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-1360567249082/control/data
[junit4:junit4] 2> 1559 T1040 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/control/data/index/
[junit4:junit4] 2> 1559 T1040 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1560 T1040 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-1360567249082/control/data/index forceNew:false
[junit4:junit4] 2> 1564 T1040 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-1360567249082/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4de29a64; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1565 T1040 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1566 T1040 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-1360567249082/control/data/index
[junit4:junit4] 2> 1566 T1040 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 1603 T1040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1603 T1040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 1604 T1040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1604 T1040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 1610 T1040 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1611 T1040 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1611 T1040 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1612 T1040 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1613 T1040 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1613 T1040 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 1614 T1040 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 1615 T1040 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1615 T1040 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 1616 T1040 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 1616 T1040 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 1617 T1040 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1617 T1040 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1618 T1040 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1619 T1040 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1619 T1040 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1620 T1040 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1623 T1040 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1623 T1040 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1666 T1040 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1667 T1040 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 1667 T1040 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 1673 T1040 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1682 T1040 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 1684 T1040 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> 1686 T1040 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-1360567249082/control/data
[junit4:junit4] 2> 1687 T1040 oass.SolrIndexSearcher.<init> Opening Searcher@5fa09291 main
[junit4:junit4] 2> 1688 T1040 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1689 T1040 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1690 T1040 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 1700 T1040 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 1732 T1041 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5fa09291 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1742 T1040 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1743 T1040 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1744 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x51 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 2118 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2119 T1038 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:49586_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49586"}
[junit4:junit4] 2> 2119 T1038 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2119 T1038 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2120 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x59 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 2127 T1037 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> 2751 T1040 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2752 T1040 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49586 collection:control_collection shard:shard1
[junit4:junit4] 2> 2754 T1040 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2768 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:delete cxid:0x73 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> 2773 T1040 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2774 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x74 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2777 T1040 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2778 T1040 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2778 T1040 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49586/collection1/
[junit4:junit4] 2> 2778 T1040 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2778 T1040 oasc.SyncStrategy.syncToMe http://127.0.0.1:49586/collection1/ has no replicas
[junit4:junit4] 2> 2779 T1040 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49586/collection1/
[junit4:junit4] 2> 2779 T1040 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2788 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50003 type:create cxid:0x7e zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3634 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3655 T1037 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> 3711 T1040 oasc.ZkController.register We are http://127.0.0.1:49586/collection1/ and leader is http://127.0.0.1:49586/collection1/
[junit4:junit4] 2> 3712 T1040 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49586
[junit4:junit4] 2> 3712 T1040 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3713 T1040 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3713 T1040 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3715 T1040 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3717 T1015 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3718 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3718 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3723 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3726 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@b493610
[junit4:junit4] 2> 3727 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3728 T1042 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3729 T1042 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 3729 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49589
[junit4:junit4] 2> 3730 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49589
[junit4:junit4] 2> 3731 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50004 with negotiated timeout 10000 for client /127.0.0.1:49589
[junit4:junit4] 2> 3731 T1042 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50004, negotiated timeout = 10000
[junit4:junit4] 2> 3731 T1043 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b493610 name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3732 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3734 T1015 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3736 T1015 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3937 T1015 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3942 T1015 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49590
[junit4:junit4] 2> 3944 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3944 T1015 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3945 T1015 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-1360567252804
[junit4:junit4] 2> 3945 T1015 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-1360567252804/solr.xml
[junit4:junit4] 2> 3946 T1015 oasc.CoreContainer.<init> New CoreContainer 1101891044
[junit4:junit4] 2> 3947 T1015 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-1360567252804/'
[junit4:junit4] 2> 3947 T1015 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-1360567252804/'
[junit4:junit4] 2> 3998 T1015 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 3998 T1015 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3999 T1015 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3999 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4000 T1015 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4000 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4001 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4003 T1015 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4003 T1015 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4004 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4015 T1015 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4031 T1015 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49583/solr
[junit4:junit4] 2> 4032 T1015 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4033 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@70f9cd4e
[junit4:junit4] 2> 4034 T1053 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4034 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4036 T1053 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 4036 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49591
[junit4:junit4] 2> 4037 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49591
[junit4:junit4] 2> 4043 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50005 with negotiated timeout 20000 for client /127.0.0.1:49591
[junit4:junit4] 2> 4043 T1053 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50005, negotiated timeout = 20000
[junit4:junit4] 2> 4046 T1054 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70f9cd4e name:ZooKeeperConnection Watcher:127.0.0.1:49583 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4046 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4049 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c50005
[junit4:junit4] 2> 4050 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49591 which had sessionid 0x13cc820a8c50005
[junit4:junit4] 2> 4051 T1054 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4051 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c50005 closed
[junit4:junit4] 2> 4052 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 4056 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@233b5a7c
[junit4:junit4] 2> 4058 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4058 T1055 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4059 T1055 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 4059 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49592
[junit4:junit4] 2> 4060 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49592
[junit4:junit4] 2> 4062 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50006 with negotiated timeout 20000 for client /127.0.0.1:49592
[junit4:junit4] 2> 4062 T1055 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50006, negotiated timeout = 20000
[junit4:junit4] 2> 4062 T1056 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@233b5a7c name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4063 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4064 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4066 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4068 T1015 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4072 T1015 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49590_
[junit4:junit4] 2> 4073 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49590_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49590_
[junit4:junit4] 2> 4074 T1015 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49590_
[junit4:junit4] 2> 4078 T1037 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 4080 T1043 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4082 T1056 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4083 T1037 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4091 T1057 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-1360567252804/collection1
[junit4:junit4] 2> 4091 T1057 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4092 T1057 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4093 T1057 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4095 T1057 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-1360567252804/collection1/'
[junit4:junit4] 2> 4095 T1057 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-1360567252804/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4096 T1057 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-1360567252804/collection1/lib/README' to classloader
[junit4:junit4] 2> 4165 T1057 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 4236 T1057 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4238 T1057 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4248 T1057 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 4917 T1057 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 4931 T1057 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 4936 T1057 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 4965 T1057 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4971 T1057 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4978 T1057 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4980 T1057 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4982 T1057 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-1360567252804/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty1/
[junit4:junit4] 2> 4982 T1057 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@409315af
[junit4:junit4] 2> 4983 T1057 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 4984 T1057 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-1360567249082/jetty1 forceNew:false
[junit4:junit4] 2> 4984 T1057 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-1360567249082/jetty1
[junit4:junit4] 2> 4985 T1057 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty1/index/
[junit4:junit4] 2> 4985 T1057 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 4987 T1057 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-1360567249082/jetty1/index forceNew:false
[junit4:junit4] 2> 4998 T1057 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-1360567249082/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f80e78; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 4999 T1057 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 4999 T1057 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-1360567249082/jetty1/index
[junit4:junit4] 2> 5000 T1057 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 5003 T1057 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5003 T1057 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 5004 T1057 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5004 T1057 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 5005 T1057 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5005 T1057 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5006 T1057 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5007 T1057 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5007 T1057 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5008 T1057 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 5009 T1057 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 5009 T1057 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5011 T1057 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 5011 T1057 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 5011 T1057 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 5012 T1057 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5013 T1057 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5014 T1057 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5015 T1057 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5016 T1057 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5017 T1057 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5018 T1057 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5018 T1057 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5019 T1057 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5020 T1057 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 5021 T1057 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 5032 T1057 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5035 T1057 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 5039 T1057 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> 5042 T1057 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-1360567249082/jetty1
[junit4:junit4] 2> 5043 T1057 oass.SolrIndexSearcher.<init> Opening Searcher@5dc58032 main
[junit4:junit4] 2> 5044 T1057 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5044 T1057 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5045 T1057 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 5050 T1057 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 5087 T1058 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5dc58032 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5103 T1057 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5104 T1057 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 5165 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5171 T1038 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:49586_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49586"}
[junit4:junit4] 2> 5177 T1038 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:49590_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49590"}
[junit4:junit4] 2> 5177 T1038 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 5178 T1038 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 5185 T1056 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> 5186 T1043 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> 5186 T1037 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> 6107 T1057 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6107 T1057 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49590 collection:collection1 shard:shard1
[junit4:junit4] 2> 6109 T1057 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 6118 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50006 type:delete cxid:0x45 zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 6119 T1057 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 6120 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50006 type:create cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6123 T1057 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 6123 T1057 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 6124 T1057 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49590/collection1/
[junit4:junit4] 2> 6124 T1057 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 6125 T1057 oasc.SyncStrategy.syncToMe http://127.0.0.1:49590/collection1/ has no replicas
[junit4:junit4] 2> 6125 T1057 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49590/collection1/
[junit4:junit4] 2> 6125 T1057 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 6132 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50006 type:create cxid:0x50 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6702 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6731 T1037 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> 6734 T1043 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> 6734 T1056 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> 6758 T1057 oasc.ZkController.register We are http://127.0.0.1:49590/collection1/ and leader is http://127.0.0.1:49590/collection1/
[junit4:junit4] 2> 6759 T1057 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49590
[junit4:junit4] 2> 6759 T1057 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 6759 T1057 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 6760 T1057 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6762 T1057 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6764 T1015 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 6765 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 6766 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 6973 T1015 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 6978 T1015 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49593
[junit4:junit4] 2> 6978 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 6979 T1015 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 6980 T1015 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-1360567255842
[junit4:junit4] 2> 6980 T1015 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-1360567255842/solr.xml
[junit4:junit4] 2> 6981 T1015 oasc.CoreContainer.<init> New CoreContainer 781030089
[junit4:junit4] 2> 6982 T1015 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-1360567255842/'
[junit4:junit4] 2> 6982 T1015 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-1360567255842/'
[junit4:junit4] 2> 7035 T1015 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 7035 T1015 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 7036 T1015 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 7036 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 7037 T1015 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 7038 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 7038 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 7039 T1015 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 7039 T1015 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 7040 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 7052 T1015 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 7076 T1015 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49583/solr
[junit4:junit4] 2> 7077 T1015 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 7078 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@5bea13da
[junit4:junit4] 2> 7079 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7079 T1068 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 7081 T1068 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 7081 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49594
[junit4:junit4] 2> 7081 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49594
[junit4:junit4] 2> 7085 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50007 with negotiated timeout 20000 for client /127.0.0.1:49594
[junit4:junit4] 2> 7085 T1068 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50007, negotiated timeout = 20000
[junit4:junit4] 2> 7085 T1069 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bea13da name:ZooKeeperConnection Watcher:127.0.0.1:49583 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7086 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7089 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c50007
[junit4:junit4] 2> 7090 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49594 which had sessionid 0x13cc820a8c50007
[junit4:junit4] 2> 7090 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c50007 closed
[junit4:junit4] 2> 7090 T1069 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 7091 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 7096 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ec68078
[junit4:junit4] 2> 7097 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7098 T1070 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 7098 T1070 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 7099 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49595
[junit4:junit4] 2> 7099 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49595
[junit4:junit4] 2> 7101 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50008 with negotiated timeout 20000 for client /127.0.0.1:49595
[junit4:junit4] 2> 7101 T1070 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50008, negotiated timeout = 20000
[junit4:junit4] 2> 7102 T1071 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ec68078 name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7102 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7104 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7106 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50008 type:create cxid:0x2 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7108 T1015 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 7112 T1015 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49593_
[junit4:junit4] 2> 7113 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50008 type:delete cxid:0x9 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49593_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49593_
[junit4:junit4] 2> 7114 T1015 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49593_
[junit4:junit4] 2> 7117 T1037 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> 7118 T1043 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> 7118 T1056 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> 7123 T1071 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7127 T1056 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7127 T1037 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7128 T1043 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7143 T1072 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-1360567255842/collection1
[junit4:junit4] 2> 7143 T1072 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 7145 T1072 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 7145 T1072 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 7148 T1072 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-1360567255842/collection1/'
[junit4:junit4] 2> 7149 T1072 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-1360567255842/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 7150 T1072 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-1360567255842/collection1/lib/README' to classloader
[junit4:junit4] 2> 7221 T1072 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 7293 T1072 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 7302 T1072 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 7308 T1072 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 7994 T1072 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 8009 T1072 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 8012 T1072 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 8039 T1072 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 8045 T1072 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 8051 T1072 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 8053 T1072 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 8055 T1072 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-1360567255842/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty2/
[junit4:junit4] 2> 8055 T1072 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@409315af
[junit4:junit4] 2> 8056 T1072 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 8057 T1072 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-1360567249082/jetty2 forceNew:false
[junit4:junit4] 2> 8058 T1072 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-1360567249082/jetty2
[junit4:junit4] 2> 8058 T1072 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty2/index/
[junit4:junit4] 2> 8058 T1072 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 8060 T1072 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-1360567249082/jetty2/index forceNew:false
[junit4:junit4] 2> 8071 T1072 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-1360567249082/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cc03c01; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 8072 T1072 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 8073 T1072 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-1360567249082/jetty2/index
[junit4:junit4] 2> 8074 T1072 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 8077 T1072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 8077 T1072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 8078 T1072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 8078 T1072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 8079 T1072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 8079 T1072 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 8080 T1072 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 8081 T1072 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 8081 T1072 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 8083 T1072 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 8084 T1072 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 8085 T1072 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 8086 T1072 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 8086 T1072 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 8087 T1072 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 8087 T1072 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 8088 T1072 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8089 T1072 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8090 T1072 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8091 T1072 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8091 T1072 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8092 T1072 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8094 T1072 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8094 T1072 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8095 T1072 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 8096 T1072 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 8103 T1072 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 8106 T1072 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 8108 T1072 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> 8111 T1072 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-1360567249082/jetty2
[junit4:junit4] 2> 8112 T1072 oass.SolrIndexSearcher.<init> Opening Searcher@45d39891 main
[junit4:junit4] 2> 8113 T1072 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 8114 T1072 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 8114 T1072 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 8120 T1072 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 8160 T1073 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@45d39891 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 8168 T1072 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 8168 T1072 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8242 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8244 T1038 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:49590_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49590"}
[junit4:junit4] 2> 8249 T1038 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:49593_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49593"}
[junit4:junit4] 2> 8250 T1038 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 8250 T1038 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 8256 T1071 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> 8257 T1037 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> 8257 T1043 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> 8258 T1056 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> 9172 T1072 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 9172 T1072 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49593 collection:collection1 shard:shard2
[junit4:junit4] 2> 9173 T1072 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 9180 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50008 type:delete cxid:0x44 zxid:0x7c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4] 2> 9181 T1072 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 9182 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50008 type:create cxid:0x45 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9184 T1072 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 9184 T1072 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 9185 T1072 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49593/collection1/
[junit4:junit4] 2> 9185 T1072 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 9185 T1072 oasc.SyncStrategy.syncToMe http://127.0.0.1:49593/collection1/ has no replicas
[junit4:junit4] 2> 9185 T1072 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49593/collection1/
[junit4:junit4] 2> 9185 T1072 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 9189 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c50008 type:create cxid:0x4e zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9773 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9786 T1037 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> 9787 T1071 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> 9787 T1056 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> 9787 T1043 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> 9806 T1072 oasc.ZkController.register We are http://127.0.0.1:49593/collection1/ and leader is http://127.0.0.1:49593/collection1/
[junit4:junit4] 2> 9808 T1072 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49593
[junit4:junit4] 2> 9811 T1072 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 9811 T1072 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 9811 T1072 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 9815 T1072 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9817 T1015 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 9817 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 9818 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 10023 T1015 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 10029 T1015 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49596
[junit4:junit4] 2> 10030 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 10031 T1015 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 10031 T1015 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-1360567258893
[junit4:junit4] 2> 10032 T1015 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-1360567258893/solr.xml
[junit4:junit4] 2> 10033 T1015 oasc.CoreContainer.<init> New CoreContainer 317433918
[junit4:junit4] 2> 10033 T1015 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-1360567258893/'
[junit4:junit4] 2> 10034 T1015 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-1360567258893/'
[junit4:junit4] 2> 10081 T1015 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 10082 T1015 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 10083 T1015 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 10083 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 10084 T1015 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 10084 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 10085 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 10086 T1015 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 10086 T1015 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 10087 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 10107 T1015 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 10123 T1015 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49583/solr
[junit4:junit4] 2> 10124 T1015 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 10125 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2bf4a521
[junit4:junit4] 2> 10127 T1083 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 10128 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 10128 T1083 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 10129 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49597
[junit4:junit4] 2> 10129 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49597
[junit4:junit4] 2> 10131 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c50009 with negotiated timeout 20000 for client /127.0.0.1:49597
[junit4:junit4] 2> 10131 T1083 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c50009, negotiated timeout = 20000
[junit4:junit4] 2> 10132 T1084 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2bf4a521 name:ZooKeeperConnection Watcher:127.0.0.1:49583 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 10132 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 10135 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c50009
[junit4:junit4] 2> 10136 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49597 which had sessionid 0x13cc820a8c50009
[junit4:junit4] 2> 10136 T1084 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 10136 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c50009 closed
[junit4:junit4] 2> 10140 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 10149 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@46ae0938
[junit4:junit4] 2> 10151 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 10152 T1085 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 10153 T1085 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 10153 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49598
[junit4:junit4] 2> 10154 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49598
[junit4:junit4] 2> 10156 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c5000a with negotiated timeout 20000 for client /127.0.0.1:49598
[junit4:junit4] 2> 10156 T1085 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c5000a, negotiated timeout = 20000
[junit4:junit4] 2> 10157 T1086 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@46ae0938 name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 10157 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 10161 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c5000a type:create cxid:0x1 zxid:0x8d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 10163 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c5000a type:create cxid:0x2 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 10166 T1015 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 10170 T1015 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49596_
[junit4:junit4] 2> 10172 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c5000a type:delete cxid:0x9 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49596_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49596_
[junit4:junit4] 2> 10173 T1015 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49596_
[junit4:junit4] 2> 10177 T1056 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> 10177 T1037 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> 10177 T1043 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> 10180 T1071 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 10180 T1086 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 10180 T1071 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> 10185 T1056 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 10186 T1037 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 10187 T1043 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 10197 T1087 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-1360567258893/collection1
[junit4:junit4] 2> 10198 T1087 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 10199 T1087 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 10199 T1087 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 10202 T1087 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-1360567258893/collection1/'
[junit4:junit4] 2> 10203 T1087 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-1360567258893/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 10203 T1087 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-1360567258893/collection1/lib/README' to classloader
[junit4:junit4] 2> 10270 T1087 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 10347 T1087 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 10349 T1087 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 10363 T1087 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 11062 T1087 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 11088 T1087 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 11092 T1087 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 11115 T1087 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 11127 T1087 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 11135 T1087 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 11138 T1087 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 11141 T1087 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-1360567258893/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty3/
[junit4:junit4] 2> 11142 T1087 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@409315af
[junit4:junit4] 2> 11143 T1087 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 11144 T1087 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-1360567249082/jetty3 forceNew:false
[junit4:junit4] 2> 11145 T1087 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-1360567249082/jetty3
[junit4:junit4] 2> 11145 T1087 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty3/index/
[junit4:junit4] 2> 11147 T1087 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 11148 T1087 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-1360567249082/jetty3/index forceNew:false
[junit4:junit4] 2> 11156 T1087 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-1360567249082/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6022bb5c; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11159 T1087 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11160 T1087 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-1360567249082/jetty3/index
[junit4:junit4] 2> 11161 T1087 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 11163 T1087 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 11164 T1087 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 11164 T1087 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 11165 T1087 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 11166 T1087 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 11167 T1087 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 11168 T1087 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 11168 T1087 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 11169 T1087 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 11171 T1087 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 11171 T1087 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 11172 T1087 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 11173 T1087 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 11173 T1087 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 11174 T1087 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 11175 T1087 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 11175 T1087 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11176 T1087 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11177 T1087 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11178 T1087 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11179 T1087 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11180 T1087 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11180 T1087 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11181 T1087 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 11182 T1087 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 11183 T1087 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 11189 T1087 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 11192 T1087 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 11199 T1087 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> 11201 T1087 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-1360567249082/jetty3
[junit4:junit4] 2> 11202 T1087 oass.SolrIndexSearcher.<init> Opening Searcher@5990fe35 main
[junit4:junit4] 2> 11203 T1087 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 11203 T1087 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 11204 T1087 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 11212 T1087 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 11256 T1088 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5990fe35 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 11269 T1087 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 11269 T1087 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11304 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11306 T1038 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:49593_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49593"}
[junit4:junit4] 2> 11312 T1038 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:49596_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49596"}
[junit4:junit4] 2> 11312 T1038 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 11313 T1038 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11320 T1037 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> 11321 T1071 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> 11321 T1086 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> 11321 T1056 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> 11322 T1043 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> 12276 T1087 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 12280 T1087 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49596 collection:collection1 shard:shard1
[junit4:junit4] 2> 12288 T1087 oasc.ZkController.register We are http://127.0.0.1:49596/collection1/ and leader is http://127.0.0.1:49590/collection1/
[junit4:junit4] 2> 12289 T1087 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49596
[junit4:junit4] 2> 12289 T1087 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 12290 T1087 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C52 name=collection1 org.apache.solr.core.SolrCore@119d8d13 url=http://127.0.0.1:49596/collection1 node=127.0.0.1:49596_ C52_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49596_, base_url=http://127.0.0.1:49596}
[junit4:junit4] 2> 12292 T1089 C52 P49596 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 12292 T1087 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12293 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 12294 T1089 C52 P49596 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 12295 T1089 C52 P49596 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12296 T1015 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 12297 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 12298 T1089 C52 P49596 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12298 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12535 T1015 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 12538 T1015 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49600
[junit4:junit4] 2> 12540 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 12541 T1015 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 12541 T1015 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-1360567261382
[junit4:junit4] 2> 12542 T1015 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-1360567261382/solr.xml
[junit4:junit4] 2> 12542 T1015 oasc.CoreContainer.<init> New CoreContainer 1687337539
[junit4:junit4] 2> 12543 T1015 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-1360567261382/'
[junit4:junit4] 2> 12544 T1015 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-1360567261382/'
[junit4:junit4] 2> 12592 T1015 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 12593 T1015 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 12593 T1015 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 12594 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 12594 T1015 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 12595 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 12595 T1015 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 12596 T1015 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 12596 T1015 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 12597 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 12624 T1015 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 12642 T1015 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49583/solr
[junit4:junit4] 2> 12643 T1015 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 12643 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@47253104
[junit4:junit4] 2> 12645 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12646 T1099 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 12647 T1099 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 12647 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49601
[junit4:junit4] 2> 12648 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49601
[junit4:junit4] 2> 12650 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c5000b with negotiated timeout 20000 for client /127.0.0.1:49601
[junit4:junit4] 2> 12650 T1099 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c5000b, negotiated timeout = 20000
[junit4:junit4] 2> 12650 T1100 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47253104 name:ZooKeeperConnection Watcher:127.0.0.1:49583 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12651 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12658 T1020 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc820a8c5000b
[junit4:junit4] 2> 12660 T1017 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49601 which had sessionid 0x13cc820a8c5000b
[junit4:junit4] 2> 12660 T1015 oaz.ZooKeeper.close Session: 0x13cc820a8c5000b closed
[junit4:junit4] 2> 12660 T1100 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 12661 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 12667 T1015 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49583/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5fe95ca8
[junit4:junit4] 2> 12669 T1015 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12670 T1101 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49583. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 12671 T1101 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49583, initiating session
[junit4:junit4] 2> 12671 T1017 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49602
[junit4:junit4] 2> 12672 T1017 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49602
[junit4:junit4] 2> 12673 T1019 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc820a8c5000c with negotiated timeout 20000 for client /127.0.0.1:49602
[junit4:junit4] 2> 12674 T1101 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49583, sessionid = 0x13cc820a8c5000c, negotiated timeout = 20000
[junit4:junit4] 2> 12674 T1102 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5fe95ca8 name:ZooKeeperConnection Watcher:127.0.0.1:49583/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12675 T1015 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12677 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c5000c type:create cxid:0x1 zxid:0x9f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12679 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c5000c type:create cxid:0x2 zxid:0xa0 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12681 T1015 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12684 T1015 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49600_
[junit4:junit4] 2> 12685 T1020 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc820a8c5000c type:delete cxid:0x9 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49600_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49600_
[junit4:junit4] 2> 12686 T1015 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49600_
[junit4:junit4] 2> 12690 T1043 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> 12690 T1037 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> 12690 T1056 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> 12693 T1086 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 12694 T1086 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> 12694 T1071 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 12694 T1071 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> 12695 T1102 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 12702 T1037 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 12703 T1056 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 12703 T1043 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 12713 T1103 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-1360567261382/collection1
[junit4:junit4] 2> 12713 T1103 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 12714 T1103 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 12715 T1103 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 12717 T1103 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-1360567261382/collection1/'
[junit4:junit4] 2> 12719 T1103 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-1360567261382/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 12719 T1103 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-1360567261382/collection1/lib/README' to classloader
[junit4:junit4] 2> 12791 T1103 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 12873 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12875 T1038 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:49596_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49596"}
[junit4:junit4] 2> 12883 T1103 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 12886 T1037 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> 12886 T1086 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> 12887 T1043 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> 12887 T1071 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> 12887 T1056 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> 12888 T1102 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> 12894 T1103 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 12919 T1103 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13631 T1103 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13657 T1103 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13662 T1103 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13685 T1103 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13689 T1103 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13693 T1103 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13694 T1103 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13695 T1103 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-1360567261382/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty4/
[junit4:junit4] 2> 13696 T1103 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@409315af
[junit4:junit4] 2> 13696 T1103 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 13697 T1103 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-1360567249082/jetty4 forceNew:false
[junit4:junit4] 2> 13697 T1103 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-1360567249082/jetty4
[junit4:junit4] 2> 13697 T1103 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty4/index/
[junit4:junit4] 2> 13698 T1103 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13699 T1103 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-1360567249082/jetty4/index forceNew:false
[junit4:junit4] 2> 13704 T1103 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-1360567249082/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a2e4036; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13704 T1103 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13705 T1103 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-1360567249082/jetty4/index
[junit4:junit4] 2> 13706 T1103 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 13708 T1103 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13710 T1103 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 13710 T1103 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13711 T1103 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 13712 T1103 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13712 T1103 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13713 T1103 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13714 T1103 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13715 T1103 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13716 T1103 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 13717 T1103 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 13718 T1103 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13719 T1103 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 13720 T1103 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 13720 T1103 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 13722 T1103 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13723 T1103 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13724 T1103 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13725 T1103 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13728 T1103 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13732 T1103 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13733 T1103 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13734 T1103 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13735 T1103 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13735 T1103 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 13736 T1103 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 13743 T1103 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13747 T1103 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 13749 T1103 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> 13752 T1103 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-1360567249082/jetty4
[junit4:junit4] 2> 13754 T1103 oass.SolrIndexSearcher.<init> Opening Searcher@7501dca0 main
[junit4:junit4] 2> 13755 T1103 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13755 T1103 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13756 T1103 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 13762 T1103 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 13802 T1104 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7501dca0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13810 T1103 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13810 T1103 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14401 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14403 T1038 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:49600_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49600"}
[junit4:junit4] 2> 14403 T1038 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 14404 T1038 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 14412 T1037 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> 14416 T1086 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> 14421 T1056 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> 14423 T1071 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> 14424 T1102 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> 14426 T1043 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> 14814 T1103 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 14815 T1103 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49600 collection:collection1 shard:shard2
[junit4:junit4] 2> 14822 T1103 oasc.ZkController.register We are http://127.0.0.1:49600/collection1/ and leader is http://127.0.0.1:49593/collection1/
[junit4:junit4] 2> 14822 T1103 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49600
[junit4:junit4] 2> 14823 T1103 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 14823 T1103 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C53 name=collection1 org.apache.solr.core.SolrCore@6262e0a7 url=http://127.0.0.1:49600/collection1 node=127.0.0.1:49600_ C53_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49600_, base_url=http://127.0.0.1:49600}
[junit4:junit4] 2> 14825 T1105 C53 P49600 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 14826 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 14826 T1103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14826 T1105 C53 P49600 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 14826 T1105 C53 P49600 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14827 T1015 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 14828 T1105 C53 P49600 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14828 T1015 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 14828 T1015 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14837 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14839 T1015 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 14840 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C52_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49596_, base_url=http://127.0.0.1:49596}
[junit4:junit4] 2> 15349 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49590/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15351 T1089 C52 P49596 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49596 START replicas=[http://127.0.0.1:49590/collection1/] nUpdates=100
[junit4:junit4] 2> 15352 T1089 C52 P49596 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15354 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15354 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15354 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15355 T1089 C52 P49596 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15355 T1089 C52 P49596 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49590/collection1/. core=collection1
[junit4:junit4] 2> 15356 T1089 C52 P49596 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C54 name=collection1 org.apache.solr.core.SolrCore@3ec71283 url=http://127.0.0.1:49590/collection1 node=127.0.0.1:49590_ C54_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49590_, base_url=http://127.0.0.1:49590, leader=true}
[junit4:junit4] 2> 15366 T1052 C54 P49590 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 15371 T1047 C54 P49590 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15372 T1047 C54 P49590 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-1360567249082/jetty1
[junit4:junit4] 2> 15375 T1047 C54 P49590 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-1360567249082/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f80e78; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15376 T1047 C54 P49590 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15380 T1047 C54 P49590 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-1360567249082/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f80e78; 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-1360567249082/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f80e78; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15380 T1047 C54 P49590 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15381 T1047 C54 P49590 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-1360567249082/jetty1
[junit4:junit4] 2> 15382 T1047 C54 P49590 oass.SolrIndexSearcher.<init> Opening Searcher@228815e9 realtime
[junit4:junit4] 2> 15382 T1047 C54 P49590 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15383 T1047 C54 P49590 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 15384 T1089 C52 P49596 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15385 T1089 C52 P49596 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15389 T1050 C54 P49590 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15390 T1050 C54 P49590 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 2> 15391 T1089 C52 P49596 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 15391 T1089 C52 P49596 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15392 T1089 C52 P49596 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15394 T1051 C54 P49590 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-1360567249082/jetty1
[junit4:junit4] 2> 15395 T1051 C54 P49590 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-1360567249082/jetty1/index
[junit4:junit4] 2> 15396 T1051 C54 P49590 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2
[junit4:junit4] 2> 15397 T1089 C52 P49596 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15398 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465 forceNew:false
[junit4:junit4] 2> 15399 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15400 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465 lockFactory=org.apache.lucene.store.NativeFSLockFactory@35d3e0e8; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 15413 T1049 C54 P49590 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 15415 T1089 C52 P49596 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-1360567249082/jetty3/index
[junit4:junit4] 2> 15416 T1089 C52 P49596 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15417 T1089 C52 P49596 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130210215104465
[junit4:junit4] 2> 15418 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15419 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15420 T1089 C52 P49596 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty3/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty3/index.20130210215104465
[junit4:junit4] 2> 15423 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465 lockFactory=org.apache.lucene.store.NativeFSLockFactory@35d3e0e8; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15424 T1089 C52 P49596 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15427 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15428 T1089 C52 P49596 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15428 T1089 C52 P49596 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15430 T1089 C52 P49596 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 15435 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465
[junit4:junit4] 2> 15436 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15439 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465 lockFactory=org.apache.lucene.store.NativeFSLockFactory@35d3e0e8; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15440 T1089 C52 P49596 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15440 T1089 C52 P49596 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15441 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15442 T1089 C52 P49596 oass.SolrIndexSearcher.<init> Opening Searcher@2c468062 main
[junit4:junit4] 2> 15444 T1088 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c468062 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 15444 T1088 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-1360567249082/jetty3/index
[junit4:junit4] 2> 15445 T1089 C52 P49596 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15448 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465 lockFactory=org.apache.lucene.store.NativeFSLockFactory@35d3e0e8; 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-1360567249082/jetty3/index.20130210215104465 lockFactory=org.apache.lucene.store.NativeFSLockFactory@35d3e0e8; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15449 T1089 C52 P49596 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15450 T1089 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 15450 T1089 C52 P49596 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15451 T1089 C52 P49596 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-1360567249082/jetty3/index.20130210215104465
[junit4:junit4] 2> 15451 T1089 C52 P49596 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-1360567249082/jetty3/index
[junit4:junit4] 2> 15451 T1089 C52 P49596 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15451 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15452 T1089 C52 P49596 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15452 T1089 C52 P49596 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15456 T1089 C52 P49596 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15848 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15923 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15924 T1038 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:49600_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49600"}
[junit4:junit4] 2> 15931 T1038 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:49596_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49596"}
[junit4:junit4] 2> 15938 T1071 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> 15938 T1037 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> 15939 T1102 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> 15939 T1043 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> 15939 T1056 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> 15945 T1086 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> 16853 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17857 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C53_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49600_, base_url=http://127.0.0.1:49600}
[junit4:junit4] 2> 18841 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49593/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 18842 T1105 C53 P49600 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49600 START replicas=[http://127.0.0.1:49593/collection1/] nUpdates=100
[junit4:junit4] 2> 18843 T1105 C53 P49600 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 18843 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 18844 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 18844 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 18845 T1105 C53 P49600 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 18845 T1105 C53 P49600 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49593/collection1/. core=collection1
[junit4:junit4] 2> 18846 T1105 C53 P49600 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18867 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C55 name=collection1 org.apache.solr.core.SolrCore@6522008b url=http://127.0.0.1:49593/collection1 node=127.0.0.1:49593_ C55_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49593_, base_url=http://127.0.0.1:49593, leader=true}
[junit4:junit4] 2> 18872 T1065 C55 P49593 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 18875 T1065 C55 P49593 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-1360567249082/jetty2
[junit4:junit4] 2> 18878 T1065 C55 P49593 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-1360567249082/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cc03c01; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 18879 T1065 C55 P49593 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 18883 T1065 C55 P49593 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-1360567249082/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cc03c01; 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-1360567249082/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7cc03c01; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 18883 T1065 C55 P49593 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 18885 T1064 C55 P49593 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 18885 T1065 C55 P49593 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-1360567249082/jetty2
[junit4:junit4] 2> 18885 T1065 C55 P49593 oass.SolrIndexSearcher.<init> Opening Searcher@535f2cd0 realtime
[junit4:junit4] 2> 18886 T1065 C55 P49593 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18886 T1065 C55 P49593 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 18887 T1105 C53 P49600 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18888 T1105 C53 P49600 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 18890 T1061 C55 P49593 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18891 T1061 C55 P49593 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 18891 T1105 C53 P49600 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 18891 T1105 C53 P49600 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 18891 T1105 C53 P49600 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 18894 T1063 C55 P49593 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-1360567249082/jetty2
[junit4:junit4] 2> 18894 T1063 C55 P49593 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-1360567249082/jetty2/index
[junit4:junit4] 2> 18894 T1063 C55 P49593 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 18895 T1105 C53 P49600 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 18897 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964 forceNew:false
[junit4:junit4] 2> 18897 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18898 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cf74267; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 18902 T1062 C55 P49593 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 18904 T1105 C53 P49600 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-1360567249082/jetty4/index
[junit4:junit4] 2> 18905 T1105 C53 P49600 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 18905 T1105 C53 P49600 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130210215107964
[junit4:junit4] 2> 18907 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18908 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18908 T1105 C53 P49600 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty4/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360567249082/jetty4/index.20130210215107964
[junit4:junit4] 2> 18918 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cf74267; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 18919 T1105 C53 P49600 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 18920 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18920 T1105 C53 P49600 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 18921 T1105 C53 P49600 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 18921 T1105 C53 P49600 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 18922 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964
[junit4:junit4] 2> 18923 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18926 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cf74267; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 18926 T1105 C53 P49600 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 18926 T1105 C53 P49600 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 18927 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18931 T1105 C53 P49600 oass.SolrIndexSearcher.<init> Opening Searcher@10bf9994 main
[junit4:junit4] 2> 18935 T1104 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10bf9994 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 18936 T1104 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-1360567249082/jetty4/index
[junit4:junit4] 2> 18936 T1105 C53 P49600 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 18939 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cf74267; 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-1360567249082/jetty4/index.20130210215107964 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4cf74267; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18940 T1105 C53 P49600 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18941 T1105 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 18941 T1105 C53 P49600 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18941 T1105 C53 P49600 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-1360567249082/jetty4/index.20130210215107964
[junit4:junit4] 2> 18942 T1105 C53 P49600 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-1360567249082/jetty4/index
[junit4:junit4] 2> 18942 T1105 C53 P49600 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 18942 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 18943 T1105 C53 P49600 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 18943 T1105 C53 P49600 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18945 T1105 C53 P49600 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 18960 T1038 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18961 T1038 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:49600_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49600"}
[junit4:junit4] 2> 18969 T1071 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> 18970 T1037 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> 18970 T1086 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> 18971 T1102 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> 18971 T1056 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> 18971 T1043 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> 19880 T1015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19885 T1015 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C56 name=collection1 org.apache.solr.core.SolrCore@a172f80 url=http://127.0.0.1:49586/collection1 node=127.0.0.1:49586_ C56_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49586_, base_url=http://127.0.0.1:49586, leader=true}
[junit4:junit4] 2> 19899 T1028 C56 P49586 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-1360567249082/control/data
[junit4:junit4] 2> 19903 T1028 C56 P49586 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-1360567249082/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4de29a64; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 19903 T1028 C56 P49586 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 19905 T1028 C56 P49586 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-1360567249082/control/data
[junit4:junit4] 2> 19907 T1028 C56 P49586 oass.SolrIndexSearcher.<init> Opening Searcher@42433dc1 realtime
[junit4:junit4] 2> 19907 T1028 C56 P49586 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426658184623292416)} 0 10
[junit4:junit4] 2> 19918 T1049 C54 P49590 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-1360567249082/jetty1
[junit4:junit4] 2> 19927 T1066 C55 P49593 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-1360567249082/jetty2
[junit4:junit4] 2> C53_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49600_, base_url=http://127.0.0.1:49600}
[junit4:junit4] 2> 19965 T1093 C53 P49600 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-1360567249082/jetty4
[junit4:junit4] 2> 19969 T1093 C53 P49600 /update {update.distrib=FROMLEADER&_version_=-1426658184650555392&update.from=http://127.0.0.1:49593/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1426658184650555392)} 0 7
[junit4:junit4] 2> C52_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49596_, base_url=http://127.0.0.1:49596}
[junit4:junit4] 2> 19972 T1082 C52 P49596 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-1360567249082/jetty3
[junit4:junit4] 2> 19973 T1082 C52 P49596 /update {update.distrib=FROMLEADER&_version_=-1426658184641118208&update.from=http://127.0.0.1:49590/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1426658184641118208)} 0 41
[junit4:junit4] 2> 19974 T1066 C55 P49593 /update {update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1426658184650555392)} 0 51
[junit4:junit4] 2> 19975 T1049 C54 P49590 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426658184641118208)} 0 62
[junit4:junit4] 2> 19983 T1029 C56 P49586 /update {wt=javabin&version=2} {add=[1 (1426658184708227072)]} 0 4
[junit4:junit4] 2> 20000 T1077 C52 P49596 /update {distrib.from=http://127.0.0.1:49590/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1426658184719761408)]} 0 4
[junit4:junit4] 2> 20002 T1052 C54 P49590 /update {distrib.from=http://127.0.0.1:49593/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1426658184719761408)]} 0 13
[junit4:junit4] 2> 20003 T1061 C55 P49593 /update {wt=javabin&version=2} {add=[1]} 0 16
[junit4:junit4] 2> 20009 T1030 C56 P49586 /update {wt=javabin&version=2} {add=[2 (1426658184737587200)]} 0 2
[junit4:junit4] 2> 20023 T1094 C53 P49600 /update {distrib.from=http://127.0.0.1:49593/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1426658184747024384)]} 0 3
[junit4:junit4] 2> 20024 T1063 C55 P49593 /update {distrib.from=http://127.0.0.1:49590/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1426658184747024384)]} 0 9
[junit4:junit4] 2> 20037 T1047 C54 P49590 /update {wt=javabin&version=2} {add=[2]} 0 24
[junit4:junit4] 2> 20050 T1031 C56 P49586 /update {wt=javabin&version=2} {add=[3 (1426658184776384512)]} 0 7
[junit4:junit4] 2> 20064 T1095 C53 P49600 /update {distrib.from=http://127.0.0.1:49593/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1426658184788967424)]} 0 4
[junit4:junit4] 2> 20066 T1062 C55 P49593 /update {wt=javabin&version=2} {add=[3 (1426658184788967424)]} 0 10
[junit4:junit4] 2> 20113 T1032 C56 P49586 /update {wt=javabin&version=2} {add=[4 (1426658184839299072)]} 0 12
[junit4:junit4] 2> 20124 T1078 C52 P49596 /update {distrib.from=http://127.0.0.1:49590/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1426658184852930560)]} 0 2
[junit4:junit4] 2> 20125 T1048 C54 P49590 /update {wt=javabin&version=2} {add=[4 (1426658184852930560)]} 0 8
[junit4:junit4] 2> 20138 T1028 C56 P49586 /update {wt=javabin&version=2} {add=[5 (1426658184872853504)]} 0 2
[junit4:junit4] 2> 20152 T1096 C53 P49600 /update {distrib.from=http://127.0.0.1:49593/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1426658184880193536)]} 0 2
[junit4:junit4] 2> 20153 T1064 C55 P49593 /update {wt=javabin&version=2} {add=[5 (1426658184880193536)]} 0 10
[junit4:junit4] 2> 20157 T1029 C56 P49586 /update {wt=javabin&version=2} {add=[6 (1426658184893825024)]} 0 1
[junit4:junit4] 2> 20168 T1097 C53 P49600 /update {distrib.from=http://127.0.0.1:49593/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1426658184901165056)]} 0 2
[junit4:junit4] 2> 20169 T1066 C55 P49593 /update {distrib.from=http://127.0.0.1:49590/col
[...truncated too long message...]
eDistributedSearchTestCase.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> 802417 T1015 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {n_f1=PostingsFormat(name=NestedPulsing), foo_b=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), cat=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), foo_d=MockVariableIntBlock(baseBlockSize=61), foo_f=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), n_tl1=PostingsFormat(name=NestedPulsing), n_d1=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), rnd_b=MockVariableIntBlock(baseBlockSize=61), intDefault=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), n_td1=PostingsFormat(name=NestedPulsing), timestamp=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), id=MockVariableIntBlock(baseBlockSize=61), range_facet_sl=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), range_facet_si=PostingsFormat(name=NestedPulsing), oddField_s=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), sequence_i=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), name=MockVariableIntBlock(baseBlockSize=61), foo_i=PostingsFormat(name=NestedPulsing), regex_dup_B_s=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), multiDefault=PostingsFormat(name=NestedPulsing), n_tf1=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), n_dt1=PostingsFormat(name=NestedPulsing), genre_s=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), author_t=PostingsFormat(name=NestedPulsing), n_ti1=MockVariableIntBlock(baseBlockSize=61), range_facet_l=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), text=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), _version_=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), val_i=MockVariableIntBlock(baseBlockSize=61), SubjectTerms_mfacet=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), series_t=PostingsFormat(name=NestedPulsing), a_t=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), n_tdt1=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), regex_dup_A_s=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), price=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246), other_tl1=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), n_l1=Pulsing41(freqCutoff=18 minBlockSize=89 maxBlockSize=246), a_si=PostingsFormat(name=NestedPulsing), inStock=Pulsing41(freqCutoff=20 minBlockSize=89 maxBlockSize=246)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=es_US, timezone=Pacific/Marquesas
[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=46523512,total=146452480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [ReturnFieldsTest, TestSolrXMLSerializer, RAMDirectoryFactoryTest, TestCoreContainer, CoreAdminHandlerTest, SchemaVersionSpecificBehaviorTest, TestExtendedDismaxParser, DocumentAnalysisRequestHandlerTest, SpellCheckComponentTest, SuggesterFSTTest, ShowFileRequestHandlerTest, StatelessScriptUpdateProcessorFactoryTest, DistributedTermsComponentTest, CopyFieldTest, SearchHandlerTest, IndexBasedSpellCheckerTest, DirectSolrConnectionTest, TestLMJelinekMercerSimilarityFactory, TestSolrCoreProperties, ZkCLITest, TestFastLRUCache, OpenExchangeRatesOrgProviderTest, TestUtils, BasicFunctionalityTest, TestPropInject, TestLuceneMatchVersion, SolrCoreCheckLockOnStartupTest, BinaryUpdateRequestHandlerTest, LoggingHandlerTest, TestLFUCache, TestSolrJ, TestLazyCores, SynonymTokenizerTest, ChaosMonkeySafeLeaderTest, ShardRoutingCustomTest, TestJmxIntegration, SOLR749Test, TestSystemIdResolver, CircularListTest, SampleTest, DebugComponentTest, SolrIndexConfigTest, TestBM25SimilarityFactory, TestAtomicUpdateErrorCases, MinimalSchemaTest, PreAnalyzedFieldTest, BasicZkTest, BasicDistributedZkTest]
[junit4:junit4] Completed in 802.71s, 1 test, 1 failure <<< FAILURES!
[...truncated 617 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:381: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:361: 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:183: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:447: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1202: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:865: There were test failures: 250 suites, 1040 tests, 1 failure, 13 ignored (2 assumptions)
Total time: 82 minutes 54 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.7.0 -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure