lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b79) - Build # 4720 - Still Failing!
Date Fri, 15 Mar 2013 12:38:43 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4720/
Java: 32bit/jdk1.8.0-ea-b79 -server -XX:+UseG1GC -XX:MarkStackSize=256K

1 tests failed.
REGRESSION:  org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch

Error Message:
Server at http://127.0.0.1:39834/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update

Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:39834/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([3F75D4E40D9B9645:BE935AFC7AC4F679]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	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:487)
	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 9207 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T1234 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 3 T1234 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563
[junit4:junit4]   2> 4 T1234 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 4 T1235 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 5 T1235 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 5 T1235 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 5 T1235 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 5 T1235 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 6 T1235 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 104 T1234 oasc.ZkTestServer.run start zk server on port:43861
[junit4:junit4]   2> 105 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1aa472e
[junit4:junit4]   2> 106 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 106 T1240 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 106 T1240 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 106 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33464
[junit4:junit4]   2> 107 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33464
[junit4:junit4]   2> 107 T1238 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 873 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0000 with negotiated timeout 10000 for client /127.0.0.1:33464
[junit4:junit4]   2> 873 T1240 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0000, negotiated timeout = 10000
[junit4:junit4]   2> 873 T1241 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1aa472e name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 873 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 874 T1234 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 877 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0000
[junit4:junit4]   2> 877 T1241 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 877 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33464 which had sessionid 0x13d6e075e9d0000
[junit4:junit4]   2> 877 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0000 closed
[junit4:junit4]   2> 878 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@16db02b
[junit4:junit4]   2> 878 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 878 T1242 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 879 T1242 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 879 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33465
[junit4:junit4]   2> 879 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33465
[junit4:junit4]   2> 880 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0001 with negotiated timeout 10000 for client /127.0.0.1:33465
[junit4:junit4]   2> 880 T1242 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0001, negotiated timeout = 10000
[junit4:junit4]   2> 880 T1243 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16db02b name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 880 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 880 T1234 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 883 T1234 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 885 T1234 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 887 T1234 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 888 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 889 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 892 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 892 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 895 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 896 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 897 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 898 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 900 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 901 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 903 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 903 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 905 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 906 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 908 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 908 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 910 T1234 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 911 T1234 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 912 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0001
[junit4:junit4]   2> 913 T1243 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 913 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33465 which had sessionid 0x13d6e075e9d0001
[junit4:junit4]   2> 913 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0001 closed
[junit4:junit4]   2> 975 T1234 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 981 T1234 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35189
[junit4:junit4]   2> 981 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 982 T1234 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 982 T1234 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473
[junit4:junit4]   2> 982 T1234 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/solr.xml
[junit4:junit4]   2> 983 T1234 oasc.CoreContainer.<init> New CoreContainer 16431780
[junit4:junit4]   2> 983 T1234 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/'
[junit4:junit4]   2> 983 T1234 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/'
[junit4:junit4]   2> 1001 T1234 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1002 T1234 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1002 T1234 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1002 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1003 T1234 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1003 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1003 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1004 T1234 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1004 T1234 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1004 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1010 T1234 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 1020 T1234 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43861/solr
[junit4:junit4]   2> 1021 T1234 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1021 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@13448ea
[junit4:junit4]   2> 1022 T1253 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 1022 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1023 T1253 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 1023 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33466
[junit4:junit4]   2> 1023 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33466
[junit4:junit4]   2> 1024 T1253 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0002, negotiated timeout = 20000
[junit4:junit4]   2> 1024 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0002 with negotiated timeout 20000 for client /127.0.0.1:33466
[junit4:junit4]   2> 1024 T1254 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13448ea name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1024 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1025 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0002
[junit4:junit4]   2> 1025 T1254 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 1026 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33466 which had sessionid 0x13d6e075e9d0002
[junit4:junit4]   2> 1025 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0002 closed
[junit4:junit4]   2> 1026 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1028 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4de10b
[junit4:junit4]   2> 1029 T1255 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 1029 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1030 T1255 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 1030 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33467
[junit4:junit4]   2> 1030 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33467
[junit4:junit4]   2> 1030 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0003 with negotiated timeout 20000 for client /127.0.0.1:33467
[junit4:junit4]   2> 1030 T1255 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0003, negotiated timeout = 20000
[junit4:junit4]   2> 1031 T1256 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4de10b name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1031 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1032 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1033 T1234 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 1035 T1234 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35189_
[junit4:junit4]   2> 1035 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:35189_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:35189_
[junit4:junit4]   2> 1035 T1234 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35189_
[junit4:junit4]   2> 1037 T1234 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 1041 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 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> 1042 T1234 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 1043 T1234 oasc.Overseer.start Overseer (id=89348545548451843-127.0.0.1:35189_-n_0000000000) starting
[junit4:junit4]   2> 1044 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1044 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1045 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1045 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1046 T1258 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 1046 T1234 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 1048 T1234 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 1049 T1234 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1051 T1257 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 1053 T1259 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/collection1
[junit4:junit4]   2> 1053 T1259 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 1054 T1259 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1054 T1259 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 1055 T1259 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/collection1/'
[junit4:junit4]   2> 1055 T1259 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/collection1/lib/README' to classloader
[junit4:junit4]   2> 1055 T1259 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1079 T1259 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1113 T1259 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1114 T1259 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 1117 T1259 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1445 T1259 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1451 T1259 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1453 T1259 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1462 T1259 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1465 T1259 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1467 T1259 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1468 T1259 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1468 T1259 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1468 T1259 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1469 T1259 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1469 T1259 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1469 T1259 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1470 T1259 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363350610473/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/
[junit4:junit4]   2> 1470 T1259 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@d93d61
[junit4:junit4]   2> 1470 T1259 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1470 T1259 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data forceNew: false
[junit4:junit4]   2> 1471 T1259 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/index/
[junit4:junit4]   2> 1471 T1259 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1471 T1259 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/index forceNew: false
[junit4:junit4]   2> 1472 T1259 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c864 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d54dfe),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1472 T1259 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1474 T1259 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1474 T1259 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1474 T1259 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1475 T1259 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1475 T1259 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1475 T1259 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1475 T1259 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1476 T1259 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1476 T1259 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1478 T1259 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1480 T1259 oass.SolrIndexSearcher.<init> Opening Searcher@1ab334e main
[junit4:junit4]   2> 1480 T1259 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/tlog
[junit4:junit4]   2> 1481 T1259 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1481 T1259 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1483 T1260 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ab334e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1485 T1259 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1485 T1259 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1485 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 2553 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2554 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35189_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35189",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 2554 T1257 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2554 T1257 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2554 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 2557 T1256 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> 3487 T1259 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 3487 T1259 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35189 collection:control_collection shard:shard1
[junit4:junit4]   2> 3488 T1259 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 3493 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:delete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 3493 T1259 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 3493 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3495 T1259 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 3495 T1259 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 3495 T1259 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35189/collection1/
[junit4:junit4]   2> 3495 T1259 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 3496 T1259 oasc.SyncStrategy.syncToMe http://127.0.0.1:35189/collection1/ has no replicas
[junit4:junit4]   2> 3496 T1259 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35189/collection1/
[junit4:junit4]   2> 3496 T1259 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 3498 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4060 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4065 T1256 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> 4101 T1259 oasc.ZkController.register We are http://127.0.0.1:35189/collection1/ and leader is http://127.0.0.1:35189/collection1/
[junit4:junit4]   2> 4101 T1259 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35189
[junit4:junit4]   2> 4101 T1259 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 4101 T1259 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 4102 T1259 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 4103 T1259 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4104 T1234 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 4104 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 4105 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 4108 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 4108 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@ff432
[junit4:junit4]   2> 4109 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4109 T1262 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4109 T1262 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 4109 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33468
[junit4:junit4]   2> 4110 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33468
[junit4:junit4]   2> 4110 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0004 with negotiated timeout 10000 for client /127.0.0.1:33468
[junit4:junit4]   2> 4110 T1262 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0004, negotiated timeout = 10000
[junit4:junit4]   2> 4111 T1263 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ff432 name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4111 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4113 T1234 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4114 T1234 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 4170 T1234 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 4172 T1234 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36140
[junit4:junit4]   2> 4173 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 4173 T1234 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 4174 T1234 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674
[junit4:junit4]   2> 4174 T1234 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/solr.xml
[junit4:junit4]   2> 4174 T1234 oasc.CoreContainer.<init> New CoreContainer 16520801
[junit4:junit4]   2> 4175 T1234 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/'
[junit4:junit4]   2> 4175 T1234 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/'
[junit4:junit4]   2> 4192 T1234 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 4192 T1234 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 4193 T1234 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 4193 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 4193 T1234 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 4194 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 4194 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 4194 T1234 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 4195 T1234 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 4195 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 4200 T1234 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4210 T1234 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43861/solr
[junit4:junit4]   2> 4210 T1234 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4211 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@eb454b
[junit4:junit4]   2> 4211 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4212 T1273 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4212 T1273 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 4212 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33470
[junit4:junit4]   2> 4213 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33470
[junit4:junit4]   2> 4214 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0005 with negotiated timeout 20000 for client /127.0.0.1:33470
[junit4:junit4]   2> 4214 T1273 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0005, negotiated timeout = 20000
[junit4:junit4]   2> 4214 T1274 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@eb454b name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4214 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4215 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0005
[junit4:junit4]   2> 4216 T1274 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4216 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33470 which had sessionid 0x13d6e075e9d0005
[junit4:junit4]   2> 4216 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0005 closed
[junit4:junit4]   2> 4216 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 4219 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1415b89
[junit4:junit4]   2> 4219 T1275 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4219 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4220 T1275 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 4220 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33471
[junit4:junit4]   2> 4220 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33471
[junit4:junit4]   2> 4221 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0006 with negotiated timeout 20000 for client /127.0.0.1:33471
[junit4:junit4]   2> 4221 T1275 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0006, negotiated timeout = 20000
[junit4:junit4]   2> 4221 T1276 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1415b89 name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4222 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4222 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4223 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4225 T1234 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 5227 T1234 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36140_
[junit4:junit4]   2> 5228 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:36140_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:36140_
[junit4:junit4]   2> 5229 T1234 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36140_
[junit4:junit4]   2> 5232 T1263 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5232 T1256 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5232 T1276 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5232 T1256 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> 5238 T1277 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/collection1
[junit4:junit4]   2> 5238 T1277 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 5239 T1277 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 5239 T1277 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 5244 T1277 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/collection1/'
[junit4:junit4]   2> 5244 T1277 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/collection1/lib/README' to classloader
[junit4:junit4]   2> 5244 T1277 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 5269 T1277 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 5328 T1277 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 5329 T1277 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 5333 T1277 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 5569 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5569 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35189_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35189",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:35189__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"active"}
[junit4:junit4]   2> 5572 T1263 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> 5572 T1276 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> 5572 T1256 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> 5663 T1277 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5668 T1277 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5671 T1277 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5681 T1277 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5683 T1277 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5686 T1277 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5687 T1277 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5687 T1277 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5687 T1277 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5688 T1277 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5688 T1277 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5688 T1277 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5688 T1277 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/
[junit4:junit4]   2> 5689 T1277 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@d93d61
[junit4:junit4]   2> 5689 T1277 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5689 T1277 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1 forceNew: false
[junit4:junit4]   2> 5690 T1277 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/index/
[junit4:junit4]   2> 5690 T1277 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5690 T1277 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/index forceNew: false
[junit4:junit4]   2> 5691 T1277 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ebded8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4698a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5691 T1277 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5693 T1277 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5693 T1277 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5693 T1277 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5694 T1277 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5694 T1277 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5694 T1277 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5695 T1277 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5695 T1277 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5695 T1277 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5697 T1277 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5699 T1277 oass.SolrIndexSearcher.<init> Opening Searcher@e64e5f main
[junit4:junit4]   2> 5700 T1277 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/tlog
[junit4:junit4]   2> 5700 T1277 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5700 T1277 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5703 T1278 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e64e5f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5704 T1277 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5704 T1277 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7075 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7076 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36140_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36140",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 7076 T1257 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 7077 T1257 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 7081 T1276 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> 7081 T1263 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> 7081 T1256 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> 7706 T1277 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7706 T1277 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36140 collection:collection1 shard:shard2
[junit4:junit4]   2> 7707 T1277 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 7712 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:delete cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7713 T1277 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7713 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7715 T1277 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7715 T1277 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7715 T1277 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36140/collection1/
[junit4:junit4]   2> 7715 T1277 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7716 T1277 oasc.SyncStrategy.syncToMe http://127.0.0.1:36140/collection1/ has no replicas
[junit4:junit4]   2> 7716 T1277 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36140/collection1/
[junit4:junit4]   2> 7716 T1277 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 7720 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8585 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8593 T1276 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> 8593 T1256 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> 8593 T1263 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> 8623 T1277 oasc.ZkController.register We are http://127.0.0.1:36140/collection1/ and leader is http://127.0.0.1:36140/collection1/
[junit4:junit4]   2> 8624 T1277 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36140
[junit4:junit4]   2> 8624 T1277 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 8624 T1277 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 8624 T1277 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8625 T1277 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8626 T1234 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 8627 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8627 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8687 T1234 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8690 T1234 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39834
[junit4:junit4]   2> 8690 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8691 T1234 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8691 T1234 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189
[junit4:junit4]   2> 8691 T1234 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/solr.xml
[junit4:junit4]   2> 8692 T1234 oasc.CoreContainer.<init> New CoreContainer 11915815
[junit4:junit4]   2> 8692 T1234 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/'
[junit4:junit4]   2> 8692 T1234 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/'
[junit4:junit4]   2> 8709 T1234 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8709 T1234 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8710 T1234 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8710 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8710 T1234 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8711 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8711 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8711 T1234 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8712 T1234 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8712 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8717 T1234 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8727 T1234 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43861/solr
[junit4:junit4]   2> 8727 T1234 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8728 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@bb310c
[junit4:junit4]   2> 8729 T1289 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8729 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8729 T1289 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 8729 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33475
[junit4:junit4]   2> 8730 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33475
[junit4:junit4]   2> 8730 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0007 with negotiated timeout 20000 for client /127.0.0.1:33475
[junit4:junit4]   2> 8730 T1289 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0007, negotiated timeout = 20000
[junit4:junit4]   2> 8731 T1290 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bb310c name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8731 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8732 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0007
[junit4:junit4]   2> 8732 T1290 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8732 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33475 which had sessionid 0x13d6e075e9d0007
[junit4:junit4]   2> 8732 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0007 closed
[junit4:junit4]   2> 8733 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8735 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d6b701
[junit4:junit4]   2> 8736 T1291 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8736 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8736 T1291 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 8737 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33476
[junit4:junit4]   2> 8737 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33476
[junit4:junit4]   2> 8738 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0008 with negotiated timeout 20000 for client /127.0.0.1:33476
[junit4:junit4]   2> 8738 T1291 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0008, negotiated timeout = 20000
[junit4:junit4]   2> 8738 T1292 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d6b701 name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8738 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8739 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8739 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8741 T1234 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9744 T1234 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39834_
[junit4:junit4]   2> 9745 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:39834_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:39834_
[junit4:junit4]   2> 9746 T1234 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39834_
[junit4:junit4]   2> 9748 T1256 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> 9749 T1263 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9749 T1276 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9750 T1292 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9750 T1263 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> 9750 T1276 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> 9751 T1256 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9759 T1293 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/collection1
[junit4:junit4]   2> 9759 T1293 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9760 T1293 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9760 T1293 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9762 T1293 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/collection1/'
[junit4:junit4]   2> 9763 T1293 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/collection1/lib/README' to classloader
[junit4:junit4]   2> 9764 T1293 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9804 T1293 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 9837 T1293 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9838 T1293 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9842 T1293 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 10098 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10099 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36140_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36140",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:36140__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "state":"active"}
[junit4:junit4]   2> 10102 T1276 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> 10102 T1263 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> 10102 T1292 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> 10102 T1256 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> 10172 T1293 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 10178 T1293 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 10180 T1293 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 10191 T1293 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10194 T1293 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10198 T1293 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10200 T1293 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 10200 T1293 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 10201 T1293 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10203 T1293 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 10203 T1293 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 10203 T1293 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 10204 T1293 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363350618189/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty2/
[junit4:junit4]   2> 10204 T1293 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@d93d61
[junit4:junit4]   2> 10205 T1293 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 10206 T1293 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty2 forceNew: false
[junit4:junit4]   2> 10206 T1293 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty2/index/
[junit4:junit4]   2> 10207 T1293 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 10207 T1293 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty2/index forceNew: false
[junit4:junit4]   2> 10210 T1293 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@883993 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fd6d53),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 10210 T1293 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 10213 T1293 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 10214 T1293 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 10215 T1293 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 10215 T1293 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 10216 T1293 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 10217 T1293 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 10217 T1293 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 10218 T1293 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 10219 T1293 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 10223 T1293 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 10228 T1293 oass.SolrIndexSearcher.<init> Opening Searcher@101328e main
[junit4:junit4]   2> 10228 T1293 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty2/tlog
[junit4:junit4]   2> 10229 T1293 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 10230 T1293 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 10235 T1294 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@101328e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 10237 T1293 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 10237 T1293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11606 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11607 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39834_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39834",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 11607 T1257 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 11608 T1257 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 11612 T1276 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> 11612 T1256 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> 11612 T1292 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> 11612 T1263 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> 12239 T1293 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 12240 T1293 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39834 collection:collection1 shard:shard1
[junit4:junit4]   2> 12240 T1293 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 12245 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0008 type:delete cxid:0x47 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 12246 T1293 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 12246 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0008 type:create cxid:0x48 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12247 T1293 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 12248 T1293 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 12248 T1293 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39834/collection1/
[junit4:junit4]   2> 12248 T1293 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 12248 T1293 oasc.SyncStrategy.syncToMe http://127.0.0.1:39834/collection1/ has no replicas
[junit4:junit4]   2> 12248 T1293 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39834/collection1/
[junit4:junit4]   2> 12248 T1293 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 12251 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0008 type:create cxid:0x51 zxid:0x83 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13116 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13122 T1276 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> 13122 T1263 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> 13122 T1256 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> 13122 T1292 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> 13155 T1293 oasc.ZkController.register We are http://127.0.0.1:39834/collection1/ and leader is http://127.0.0.1:39834/collection1/
[junit4:junit4]   2> 13155 T1293 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39834
[junit4:junit4]   2> 13155 T1293 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 13155 T1293 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 13155 T1293 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 13157 T1293 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13158 T1234 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 13158 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 13159 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13228 T1234 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 13230 T1234 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48409
[junit4:junit4]   2> 13231 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 13231 T1234 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 13232 T1234 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723
[junit4:junit4]   2> 13232 T1234 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/solr.xml
[junit4:junit4]   2> 13232 T1234 oasc.CoreContainer.<init> New CoreContainer 16224677
[junit4:junit4]   2> 13233 T1234 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/'
[junit4:junit4]   2> 13233 T1234 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/'
[junit4:junit4]   2> 13251 T1234 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 13252 T1234 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 13252 T1234 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 13252 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 13253 T1234 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 13253 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 13253 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 13254 T1234 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 13254 T1234 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 13254 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 13260 T1234 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 13271 T1234 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43861/solr
[junit4:junit4]   2> 13271 T1234 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 13271 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1163e57
[junit4:junit4]   2> 13272 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13272 T1305 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13273 T1305 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 13273 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33477
[junit4:junit4]   2> 13273 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33477
[junit4:junit4]   2> 13274 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d0009 with negotiated timeout 20000 for client /127.0.0.1:33477
[junit4:junit4]   2> 13274 T1305 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d0009, negotiated timeout = 20000
[junit4:junit4]   2> 13274 T1306 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1163e57 name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13275 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13276 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0009
[junit4:junit4]   2> 13276 T1306 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 13276 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33477 which had sessionid 0x13d6e075e9d0009
[junit4:junit4]   2> 13276 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0009 closed
[junit4:junit4]   2> 13277 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 13279 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d8570e
[junit4:junit4]   2> 13280 T1307 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13280 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13280 T1307 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 13280 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33478
[junit4:junit4]   2> 13281 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33478
[junit4:junit4]   2> 13281 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d000a with negotiated timeout 20000 for client /127.0.0.1:33478
[junit4:junit4]   2> 13281 T1307 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d000a, negotiated timeout = 20000
[junit4:junit4]   2> 13281 T1308 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d8570e name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13282 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13283 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d000a type:create cxid:0x1 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13283 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d000a type:create cxid:0x2 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13285 T1234 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 14287 T1234 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48409_
[junit4:junit4]   2> 14288 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d000a type:delete cxid:0xb zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:48409_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:48409_
[junit4:junit4]   2> 14290 T1234 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48409_
[junit4:junit4]   2> 14291 T1292 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> 14291 T1256 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> 14292 T1276 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14292 T1263 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14292 T1276 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> 14292 T1263 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> 14293 T1292 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14293 T1308 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14294 T1256 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14298 T1309 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/collection1
[junit4:junit4]   2> 14298 T1309 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 14298 T1309 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 14299 T1309 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 14299 T1309 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/collection1/'
[junit4:junit4]   2> 14300 T1309 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/collection1/lib/README' to classloader
[junit4:junit4]   2> 14300 T1309 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 14326 T1309 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 14354 T1309 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 14355 T1309 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 14359 T1309 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 14626 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14627 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39834_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39834",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:39834__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"active"}
[junit4:junit4]   2> 14629 T1276 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> 14630 T1263 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> 14630 T1292 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> 14630 T1308 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> 14630 T1256 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> 14674 T1309 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14680 T1309 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14682 T1309 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14695 T1309 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14697 T1309 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14700 T1309 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14701 T1309 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14701 T1309 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14701 T1309 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14702 T1309 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14702 T1309 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14703 T1309 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14703 T1309 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363350622723/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3/
[junit4:junit4]   2> 14703 T1309 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@d93d61
[junit4:junit4]   2> 14703 T1309 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14704 T1309 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3 forceNew: false
[junit4:junit4]   2> 14704 T1309 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3/index/
[junit4:junit4]   2> 14704 T1309 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14704 T1309 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3/index forceNew: false
[junit4:junit4]   2> 14705 T1309 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1313b47 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b9703d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14706 T1309 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14707 T1309 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14707 T1309 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14708 T1309 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14708 T1309 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14708 T1309 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14709 T1309 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14709 T1309 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14709 T1309 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14709 T1309 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14712 T1309 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14714 T1309 oass.SolrIndexSearcher.<init> Opening Searcher@f863f7 main
[junit4:junit4]   2> 14714 T1309 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3/tlog
[junit4:junit4]   2> 14714 T1309 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14715 T1309 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14718 T1310 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f863f7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14719 T1309 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14719 T1309 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16135 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16136 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48409_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48409",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 16136 T1257 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 16137 T1257 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 16141 T1256 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> 16142 T1292 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> 16142 T1308 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> 16142 T1263 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> 16142 T1276 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> 16721 T1309 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16722 T1309 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48409 collection:collection1 shard:shard2
[junit4:junit4]   2> 16725 T1309 oasc.ZkController.register We are http://127.0.0.1:48409/collection1/ and leader is http://127.0.0.1:36140/collection1/
[junit4:junit4]   2> 16725 T1309 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48409
[junit4:junit4]   2> 16725 T1309 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16725 T1309 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C70 name=collection1 org.apache.solr.core.SolrCore@16c4f1e url=http://127.0.0.1:48409/collection1 node=127.0.0.1:48409_ C70_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:48409_, collection=collection1, base_url=http://127.0.0.1:48409, core=collection1, state=down}
[junit4:junit4]   2> 16725 T1311 C70 P48409 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16726 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16726 T1309 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16726 T1311 C70 P48409 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16727 T1311 C70 P48409 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16727 T1311 C70 P48409 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16727 T1234 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 16728 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16728 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16790 T1234 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16792 T1234 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60063
[junit4:junit4]   2> 16793 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16793 T1234 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16793 T1234 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289
[junit4:junit4]   2> 16794 T1234 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/solr.xml
[junit4:junit4]   2> 16794 T1234 oasc.CoreContainer.<init> New CoreContainer 8839584
[junit4:junit4]   2> 16794 T1234 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/'
[junit4:junit4]   2> 16795 T1234 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/'
[junit4:junit4]   2> 16812 T1234 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16812 T1234 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16813 T1234 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16813 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16813 T1234 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16814 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16814 T1234 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16814 T1234 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16815 T1234 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16815 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16821 T1234 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16831 T1234 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43861/solr
[junit4:junit4]   2> 16832 T1234 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16832 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@12d62f9
[junit4:junit4]   2> 16833 T1322 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16833 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16834 T1322 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 16834 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33482
[junit4:junit4]   2> 16834 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33482
[junit4:junit4]   2> 16835 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d000b with negotiated timeout 20000 for client /127.0.0.1:33482
[junit4:junit4]   2> 16835 T1322 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d000b, negotiated timeout = 20000
[junit4:junit4]   2> 16835 T1323 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12d62f9 name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16835 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16836 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d000b
[junit4:junit4]   2> 16837 T1323 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16837 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33482 which had sessionid 0x13d6e075e9d000b
[junit4:junit4]   2> 16837 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d000b closed
[junit4:junit4]   2> 16838 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16840 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@ea976b
[junit4:junit4]   2> 16841 T1324 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16841 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16841 T1324 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 16841 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33483
[junit4:junit4]   2> 16841 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33483
[junit4:junit4]   2> 16842 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d000c with negotiated timeout 20000 for client /127.0.0.1:33483
[junit4:junit4]   2> 16842 T1324 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d000c, negotiated timeout = 20000
[junit4:junit4]   2> 16842 T1325 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ea976b name:ZooKeeperConnection Watcher:127.0.0.1:43861/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16842 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16843 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d000c type:create cxid:0x1 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16844 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d000c type:create cxid:0x2 zxid:0xa4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16845 T1234 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17648 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17648 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48409_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48409",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:48409__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "state":"recovering"}
[junit4:junit4]   2> 17653 T1263 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> 17653 T1308 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> 17653 T1325 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> 17653 T1256 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> 17653 T1292 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> 17653 T1276 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> 17731 T1272 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {onlyIfLeader=true&version=2&coreNodeName=127.0.0.1:48409__collection1&wt=javabin&core=collection1&action=PREPRECOVERY&nodeName=127.0.0.1:48409_&checkLive=true&state=recovering} status=0 QTime=1000 
[junit4:junit4]   2> 17847 T1234 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60063_
[junit4:junit4]   2> 17848 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d000c type:delete cxid:0xd zxid:0xa9 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:60063_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:60063_
[junit4:junit4]   2> 17849 T1234 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60063_
[junit4:junit4]   2> 17850 T1276 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> 17851 T1325 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> 17851 T1292 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17851 T1308 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17851 T1292 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> 17851 T1308 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> 17851 T1263 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17852 T1263 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> 17852 T1256 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17852 T1256 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> 17852 T1276 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17854 T1325 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17857 T1326 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/collection1
[junit4:junit4]   2> 17857 T1326 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17858 T1326 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17858 T1326 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17859 T1326 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/collection1/'
[junit4:junit4]   2> 17859 T1326 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/collection1/lib/README' to classloader
[junit4:junit4]   2> 17860 T1326 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17884 T1326 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 17928 T1326 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17929 T1326 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17932 T1326 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 18247 T1326 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 18253 T1326 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 18255 T1326 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 18265 T1326 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18268 T1326 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18270 T1326 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18271 T1326 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18272 T1326 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18272 T1326 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18273 T1326 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18273 T1326 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18273 T1326 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18273 T1326 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363350626289/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4/
[junit4:junit4]   2> 18273 T1326 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@d93d61
[junit4:junit4]   2> 18274 T1326 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18274 T1326 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4 forceNew: false
[junit4:junit4]   2> 18274 T1326 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4/index/
[junit4:junit4]   2> 18275 T1326 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 18275 T1326 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4/index forceNew: false
[junit4:junit4]   2> 18276 T1326 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17051cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@dfe502),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 18277 T1326 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 18278 T1326 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 18278 T1326 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 18279 T1326 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 18279 T1326 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 18280 T1326 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 18280 T1326 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 18280 T1326 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 18280 T1326 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 18281 T1326 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 18283 T1326 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 18285 T1326 oass.SolrIndexSearcher.<init> Opening Searcher@14c976b main
[junit4:junit4]   2> 18285 T1326 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4/tlog
[junit4:junit4]   2> 18286 T1326 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 18286 T1326 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 18289 T1327 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14c976b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 18290 T1326 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 18290 T1326 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19157 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19158 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60063_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60063",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 19158 T1257 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 19158 T1257 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 19161 T1263 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> 19161 T1276 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> 19162 T1256 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> 19162 T1325 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> 19162 T1292 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> 19161 T1308 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> 19291 T1326 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19292 T1326 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60063 collection:collection1 shard:shard1
[junit4:junit4]   2> 19294 T1326 oasc.ZkController.register We are http://127.0.0.1:60063/collection1/ and leader is http://127.0.0.1:39834/collection1/
[junit4:junit4]   2> 19294 T1326 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60063
[junit4:junit4]   2> 19294 T1326 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19295 T1326 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C71 name=collection1 org.apache.solr.core.SolrCore@11ab342 url=http://127.0.0.1:60063/collection1 node=127.0.0.1:60063_ C71_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:60063_, collection=collection1, base_url=http://127.0.0.1:60063, core=collection1, state=down}
[junit4:junit4]   2> 19295 T1328 C71 P60063 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19296 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19296 T1328 C71 P60063 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19296 T1326 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19296 T1328 C71 P60063 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19297 T1328 C71 P60063 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19297 T1234 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 19297 T1234 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19298 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19302 T1234 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19303 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19307 T1269 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/onenodecollectioncore
[junit4:junit4]   2> 19307 T1269 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19308 T1269 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19308 T1269 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19309 T1269 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19310 T1269 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19312 T1269 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19314 T1269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/onenodecollectioncore/'
[junit4:junit4]   2> 19341 T1269 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 19370 T1269 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19371 T1269 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19374 T1269 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 19693 T1269 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19709 T1269 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19712 T1269 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19723 T1269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19726 T1269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19728 T1269 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19729 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19730 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19730 T1269 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19731 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19731 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19731 T1269 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19732 T1269 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363350613674/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection/
[junit4:junit4]   2>  C70_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:48409_, collection=collection1, base_url=http://127.0.0.1:48409, core=collection1, shard=shard2, state=recovering}
[junit4:junit4]   2> 19732 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36140/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19732 T1311 C70 P48409 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48409 START replicas=[http://127.0.0.1:36140/collection1/] nUpdates=100
[junit4:junit4]   2> 19732 T1269 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@d93d61
[junit4:junit4]   2> 19733 T1311 C70 P48409 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19733 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19733 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19733 T1269 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19733 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19734 T1311 C70 P48409 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19734 T1311 C70 P48409 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36140/collection1/. core=collection1
[junit4:junit4]   2> 19734 T1311 C70 P48409 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19734 T1269 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection forceNew: false
[junit4:junit4]   2> 19734 T1269 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection/index/
[junit4:junit4]   2> 19735 T1269 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19735 T1269 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection/index forceNew: false
[junit4:junit4]   2> 19737 T1269 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@fe264e lockFactory=org.apache.lucene.store.NativeFSLockFactory@f0d122),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19738 T1269 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> ASYNC  NEW_CORE C72 name=collection1 org.apache.solr.core.SolrCore@1713b0a url=http://127.0.0.1:36140/collection1 node=127.0.0.1:36140_ C72_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:36140_, collection=collection1, base_url=http://127.0.0.1:36140, core=collection1, shard=shard2, state=active, leader=true}
[junit4:junit4]   2> 19738 T1270 C72 P36140 REQ /get {distrib=false&version=2&wt=javabin&getVersions=100&qt=/get} status=0 QTime=0 
[junit4:junit4]   2> 19740 T1269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19740 T1269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19740 T1271 C72 P36140 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19741 T1269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19741 T1269 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19742 T1271 C72 P36140 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ebded8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4698a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19742 T1269 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19742 T1271 C72 P36140 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19742 T1269 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19743 T1271 C72 P36140 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ebded8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4698a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ebded8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4698a),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19743 T1269 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19743 T1271 C72 P36140 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19743 T1269 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19743 T1271 C72 P36140 oass.SolrIndexSearcher.<init> Opening Searcher@1f34f91 realtime
[junit4:junit4]   2> 19744 T1269 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19744 T1271 C72 P36140 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19744 T1271 C72 P36140 /update {openSearcher=false&version=2&softCommit=false&commit=true&wt=javabin&waitSearcher=true&commit_end_point=true} {commit=} 0 4
[junit4:junit4]   2> 19745 T1311 C70 P48409 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19745 T1311 C70 P48409 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19746 T1269 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19747 T1272 C72 P36140 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19748 T1272 C72 P36140 REQ /replication {version=2&wt=javabin&command=indexversion&qt=/replication} status=0 QTime=2 
[junit4:junit4]   2> 19748 T1269 oass.SolrIndexSearcher.<init> Opening Searcher@c97eec main
[junit4:junit4]   2> 19748 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19749 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19749 T1269 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection/tlog
[junit4:junit4]   2> 19749 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19749 T1269 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19749 T1269 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19751 T1271 C72 P36140 REQ /replication {generation=2&version=2&wt=javabin&command=filelist&qt=/replication} status=0 QTime=1 
[junit4:junit4]   2> 19751 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19752 T1311 C70 P48409 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty3/index.20130315213029310 forceNew: false
[junit4:junit4]   2> 19752 T1331 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@c97eec main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19752 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@ad8fbc lockFactory=org.apache.lucene.store.NativeFSLockFactory@1672ef7) fullCopy=false
[junit4:junit4]   2> 19753 T1269 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 19755 T1270 C72 P36140 REQ /replication {generation=2&wt=filestream&checksum=true&command=filecontent&file=segments_2&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 19756 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19757 T1311 C70 P48409 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19757 T1311 C70 P48409 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19758 T1311 C70 P48409 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1313b47 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b9703d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1313b47 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b9703d),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19758 T1311 C70 P48409 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19758 T1311 C70 P48409 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19759 T1311 C70 P48409 oass.SolrIndexSearcher.<init> Opening Searcher@4eadff main
[junit4:junit4]   2> 19759 T1310 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4eadff main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19760 T1311 C70 P48409 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@ad8fbc lockFactory=org.apache.lucene.store.NativeFSLockFactory@1672ef7)
[junit4:junit4]   2> 19760 T1311 C70 P48409 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19760 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19760 T1311 C70 P48409 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19760 T1311 C70 P48409 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19761 T1311 C70 P48409 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 20665 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20666 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60063_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60063",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60063__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"recovering"}
[junit4:junit4]   2> 20669 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36140_",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36140",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 20669 T1257 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20669 T1257 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20672 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48409_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48409",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:48409__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "state":"active"}
[junit4:junit4]   2> 20675 T1325 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> 20675 T1292 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> 20675 T1256 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> 20675 T1263 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> 20675 T1276 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> 20675 T1308 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> 20754 T1269 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20755 T1269 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:36140 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20755 T1269 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20761 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:delete cxid:0xa8 zxid:0xc4 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 20761 T1269 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20762 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0xa9 zxid:0xc5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20763 T1269 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20764 T1269 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20764 T1269 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36140/onenodecollectioncore/
[junit4:junit4]   2> 20764 T1269 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20765 T1269 oasc.SyncStrategy.syncToMe http://127.0.0.1:36140/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20765 T1269 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36140/onenodecollectioncore/
[junit4:junit4]   2> 20765 T1269 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20768 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0xb3 zxid:0xc9 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21302 T1285 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {onlyIfLeader=true&version=2&coreNodeName=127.0.0.1:60063__collection1&wt=javabin&core=collection1&action=PREPRECOVERY&nodeName=127.0.0.1:60063_&checkLive=true&state=recovering} status=0 QTime=2000 
[junit4:junit4]   2> 22184 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22195 T1263 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> 22195 T1308 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> 22196 T1276 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> 22196 T1256 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> 22196 T1292 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> 22196 T1325 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> 22222 T1269 oasc.ZkController.register We are http://127.0.0.1:36140/onenodecollectioncore/ and leader is http://127.0.0.1:36140/onenodecollectioncore/
[junit4:junit4]   2> 22223 T1269 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:36140
[junit4:junit4]   2> 22223 T1269 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 22223 T1269 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 22224 T1269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22225 T1269 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&wt=javabin&name=onenodecollectioncore&collection=onenodecollection&roles=none&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection&action=CREATE&numShards=1} status=0 QTime=2918 
[junit4:junit4]   2> 22226 T1234 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 22227 T1234 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23228 T1234 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C71_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:60063_, collection=collection1, base_url=http://127.0.0.1:60063, core=collection1, shard=shard1, state=recovering}
[junit4:junit4]   2> 23303 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39834/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 23304 T1328 C71 P60063 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60063 START replicas=[http://127.0.0.1:39834/collection1/] nUpdates=100
[junit4:junit4]   2> 23304 T1328 C71 P60063 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 23305 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 23305 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 23305 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 23305 T1328 C71 P60063 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 23306 T1328 C71 P60063 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39834/collection1/. core=collection1
[junit4:junit4]   2> 23306 T1328 C71 P60063 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C73 name=collection1 org.apache.solr.core.SolrCore@b43b5d url=http://127.0.0.1:39834/collection1 node=127.0.0.1:39834_ C73_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:39834_, collection=collection1, base_url=http://127.0.0.1:39834, core=collection1, shard=shard1, state=active, leader=true}
[junit4:junit4]   2> 23312 T1288 C73 P39834 REQ /get {distrib=false&version=2&wt=javabin&getVersions=100&qt=/get} status=0 QTime=0 
[junit4:junit4]   2> 23313 T1287 C73 P39834 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 23314 T1287 C73 P39834 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@883993 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fd6d53),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 23315 T1287 C73 P39834 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 23316 T1287 C73 P39834 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@883993 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fd6d53),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@883993 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fd6d53),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23316 T1287 C73 P39834 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23316 T1287 C73 P39834 oass.SolrIndexSearcher.<init> Opening Searcher@c9a078 realtime
[junit4:junit4]   2> 23316 T1287 C73 P39834 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 23317 T1287 C73 P39834 /update {openSearcher=false&version=2&softCommit=false&commit=true&wt=javabin&waitSearcher=true&commit_end_point=true} {commit=} 0 4
[junit4:junit4]   2> 23318 T1328 C71 P60063 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23318 T1328 C71 P60063 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 23319 T1286 C73 P39834 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23319 T1286 C73 P39834 REQ /replication {version=2&wt=javabin&command=indexversion&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 23320 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 23320 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 23320 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 23322 T1288 C73 P39834 REQ /replication {generation=2&version=2&wt=javabin&command=filelist&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 23323 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 23324 T1328 C71 P60063 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty4/index.20130315213032882 forceNew: false
[junit4:junit4]   2> 23324 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@33fff8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f55ea) fullCopy=false
[junit4:junit4]   2> 23326 T1287 C73 P39834 REQ /replication {generation=2&wt=filestream&checksum=true&command=filecontent&file=segments_2&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 23327 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 23329 T1328 C71 P60063 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 23329 T1328 C71 P60063 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 23331 T1328 C71 P60063 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17051cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@dfe502),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17051cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@dfe502),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23331 T1328 C71 P60063 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23332 T1328 C71 P60063 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 23332 T1328 C71 P60063 oass.SolrIndexSearcher.<init> Opening Searcher@efad03 main
[junit4:junit4]   2> 23333 T1327 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@efad03 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 23334 T1328 C71 P60063 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@33fff8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f55ea)
[junit4:junit4]   2> 23334 T1328 C71 P60063 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 23335 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 23335 T1328 C71 P60063 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 23335 T1328 C71 P60063 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 23337 T1328 C71 P60063 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23704 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23705 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36140_",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36140",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:36140__onenodecollectioncore",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"active"}
[junit4:junit4]   2> 23707 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:60063_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:60063",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:60063__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"active"}
[junit4:junit4]   2> 23710 T1263 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> 23710 T1308 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> 23710 T1276 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> 23710 T1325 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> 23710 T1292 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> 23710 T1256 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> 24231 T1234 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24232 T1234 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 24232 T1234 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 24244 T1287 oejs.Response.sendError WARNING Committed before 404 Can not find: /onenodecollectioncore/update
[junit4:junit4]   2> 24245 T1234 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43861 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@16eb85a
[junit4:junit4]   2> 24245 T1287 oejs.ServletHandler.doHandle WARNING /onenodecollectioncore/update java.lang.IllegalStateException: Committed
[junit4:junit4]   2> 	at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1136)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.Response.sendError(Response.java:314)
[junit4:junit4]   2> 	at org.apache.solr.client.solrj.embedded.JettySolrRunner$Servlet404.service(JettySolrRunner.java:465)
[junit4:junit4]   2> 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1336)
[junit4:junit4]   2> 	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:379)
[junit4:junit4]   2> 	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:141)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4]   2> 	at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:135)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:275)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1074)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.Server.handle(Server.java:365)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998)
[junit4:junit4]   2> 	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:948)
[junit4:junit4]   2> 	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
[junit4:junit4]   2> 	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
[junit4:junit4]   2> 	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
[junit4:junit4]   2> 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 24246 T1335 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:43861. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 24245 T1234 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 24247 T1236 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:33500
[junit4:junit4]   2> 24247 T1335 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:43861, initiating session
[junit4:junit4]   2> 24247 T1236 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:33500
[junit4:junit4]   2> 24248 T1238 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6e075e9d000d with negotiated timeout 10000 for client /127.0.0.1:33500
[junit4:junit4]   2> 24248 T1335 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:43861, sessionid = 0x13d6e075e9d000d, negotiated timeout = 10000
[junit4:junit4]   2> 24248 T1336 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16eb85a name:ZooKeeperConnection Watcher:127.0.0.1:43861 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 24249 T1234 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 24289 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d000d
[junit4:junit4]   2> 24289 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33500 which had sessionid 0x13d6e075e9d000d
[junit4:junit4]   2> 24290 T1336 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 24290 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d000d closed
[junit4:junit4]   2> 24290 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0004
[junit4:junit4]   2> 24291 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33468 which had sessionid 0x13d6e075e9d0004
[junit4:junit4]   2> 24291 T1263 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 24291 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0004 closed
[junit4:junit4]   2> 24293 T1234 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 35189
[junit4:junit4]   2> 24293 T1234 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=16431780
[junit4:junit4]   2> 25215 T1257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25216 T1257 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35189_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35189",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:35189__collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 25542 T1308 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> 25543 T1292 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> 25543 T1325 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> 25542 T1256 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> 25542 T1276 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> 27295 T1234 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 27295 T1234 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 27298 T1234 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@d551ed
[junit4:junit4]   2> 27301 T1234 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 27301 T1234 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 27301 T1234 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 27302 T1234 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 27302 T1234 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 27303 T1234 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/index
[junit4:junit4]   2> 27303 T1234 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data/index
[junit4:junit4]   2> 27303 T1234 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data
[junit4:junit4]   2> 27304 T1234 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/control/data
[junit4:junit4]   2> 27304 T1257 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89348545548451843-127.0.0.1:35189_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 27305 T1239 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6e075e9d0003
[junit4:junit4]   2> 27306 T1308 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> 27306 T1256 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> 27306 T1236 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:33467 which had sessionid 0x13d6e075e9d0003
[junit4:junit4]   2> 27306 T1325 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 27306 T1234 oaz.ZooKeeper.close Session: 0x13d6e075e9d0003 closed
[junit4:junit4]   2> 27307 T1276 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 27307 T1325 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> 27307 T1292 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 27307 T1276 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> 27307 T1292 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> 27308 T1308 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 27309 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:delete cxid:0xc3 zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 27309 T1276 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 27311 T1276 oasc.Overseer.start Overseer (id=89348545548451846-127.0.0.1:36140_-n_0000000001) starting
[junit4:junit4]   2> 27311 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0xc8 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 27312 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0xc9 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 27313 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0xca zxid:0xe9 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 27313 T1239 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6e075e9d0006 type:create cxid:0xcb zxid:0xea txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 27314 T1338 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 27315 T1337 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 27316 T1337 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27316 T1337 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35189_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35189",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:35189__collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 27320 T1276 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> 27320 T1308 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> 27320 T1325 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> 27320 T1292 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> 27329 T1234 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 27380 T1234 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 36140
[junit4:junit4]   2> 27381 T1234 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=16520801
[junit4:junit4]   2> 28606 T1256 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 28607 T1256 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 28607 T1256 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 28825 T1337 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 28826 T1337 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36140_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36140",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:36140__collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 28831 T1337 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36140_",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36140",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:36140__onenodecollectioncore",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "state":"down"}
[junit4:junit4]   2> 28835 T1325 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> 28835 T1292 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> 28835 T1308 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> 28835 T1276 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> 30383 T1234 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 30384 T1234 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 30385 T1234 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 30388 T1234 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@1713b0a
[junit4:junit4]   2> 30390 T1234 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 30390 T1234 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 30390 T1234 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 30391 T1234 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 30392 T1234 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 30393 T1234 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/index
[junit4:junit4]   2> 30393 T1234 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1/index
[junit4:junit4]   2> 30393 T1234 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1
[junit4:junit4]   2> 30393 T1234 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363350609563/jetty1
[junit4:junit4]   2> 30394 T1234 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@9e6631
[junit4:junit4]   2> 30397 T1234 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 30397 T1234 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 30398 T1234 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 30398 T1234 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 30399 T1234 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 30399 T1234 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/onenodecollection/index
[junit4:junit4]   2> 30399 T1234 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363350609563/one

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

ork (0)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        
[junit4:junit4]   1>  /zookeeper (1)
[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=3F75D4E40D9B9645 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=pt_PT -Dtests.timezone=Asia/Tokyo -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR   33.8s J0 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.common.SolrException: Server at http://127.0.0.1:39834/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([3F75D4E40D9B9645:BE935AFC7AC4F679]:0)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[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:487)
[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> 33760 T1234 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 33763 T1233 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> 34441 T1237 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=pt_PT, timezone=Asia/Tokyo
[junit4:junit4]   2> NOTE: Linux 3.2.0-38-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=1,free=145312608,total=289406976
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestIBSimilarityFactory, CachingDirectoryFactoryTest, SliceStateUpdateTest, TestWriterPerf, ReturnFieldsTest, PluginInfoTest, WordBreakSolrSpellCheckerTest, MinimalSchemaTest, BasicFunctionalityTest, TestSolrQueryParser, TestGroupingSearch, SchemaVersionSpecificBehaviorTest, BinaryUpdateRequestHandlerTest, ExternalFileFieldSortTest, AutoCommitTest, TestRandomDVFaceting, ScriptEngineTest, TestFieldTypeCollectionResource, DirectSolrConnectionTest, TestSweetSpotSimilarityFactory, TestValueSourceCache, TestSolrDeletionPolicy2, TestPerFieldSimilarity, PolyFieldTest, TestXIncludeConfig, CoreAdminHandlerTest, AlternateDirectoryTest, SpatialFilterTest, IndexSchemaTest, SimpleFacetsTest, TermVectorComponentTest, DocValuesTest, TestPseudoReturnFields, TestDocumentBuilder, TestStressRecovery, TestLRUCache, DistributedQueryElevationComponentTest, TestFieldResource, PeerSyncTest, TestPhraseSuggestions, SpellingQueryConverterTest, TestFaceting, SynonymTokenizerTest, TestSolrIndexConfig, ResponseLogComponentTest, ClusterStateUpdateTest, SolrIndexSplitterTest, TestQueryUtils, ChaosMonkeyNothingIsSafeTest, SystemInfoHandlerTest, TestFunctionQuery, TestFuzzyAnalyzedSuggestions, TestCoreContainer, SliceStateTest, SOLR749Test, SolrInfoMBeanTest, SoftAutoCommitTest, FileBasedSpellCheckerTest, PrimitiveFieldTypeTest, JsonLoaderTest, ZkControllerTest, DistributedTermsComponentTest, ResourceLoaderTest, DirectUpdateHandlerOptimizeTest, TestRealTimeGet, SearchHandlerTest, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J0 in 34.53s, 1 test, 1 error <<< FAILURES!

[...truncated 422 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:361: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1213: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:877: There were test failures: 272 suites, 1144 tests, 1 error, 13 ignored (7 assumptions)

Total time: 42 minutes 1 second
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.8.0-ea-b79 -server -XX:+UseG1GC -XX:MarkStackSize=256K
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message