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 (64bit/jdk1.8.0-ea-b79) - Build # 4808 - Failure!
Date Thu, 21 Mar 2013 13:15:04 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4808/
Java: 64bit/jdk1.8.0-ea-b79 -XX:+UseParallelGC

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

Error Message:
Server at http://127.0.0.1:54146/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:54146/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([DD0A1818EB265ACD:5CEC96009C793AF1]: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 9264 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T1181 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 4 T1181 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344
[junit4:junit4]   2> 4 T1181 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 5 T1182 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 5 T1182 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 6 T1182 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 6 T1182 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 6 T1182 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 7 T1182 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 105 T1181 oasc.ZkTestServer.run start zk server on port:38096
[junit4:junit4]   2> 106 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@588a6ffa
[junit4:junit4]   2> 107 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 107 T1187 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 107 T1187 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 107 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51489
[junit4:junit4]   2> 108 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51489
[junit4:junit4]   2> 108 T1185 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 849 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330000 with negotiated timeout 10000 for client /127.0.0.1:51489
[junit4:junit4]   2> 849 T1187 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330000, negotiated timeout = 10000
[junit4:junit4]   2> 851 T1188 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@588a6ffa name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 851 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 851 T1181 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 855 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330000
[junit4:junit4]   2> 856 T1188 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 856 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51489 which had sessionid 0x13d8d0dd7330000
[junit4:junit4]   2> 856 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330000 closed
[junit4:junit4]   2> 857 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@564d9a9b
[junit4:junit4]   2> 858 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 858 T1189 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 858 T1189 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 858 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51491
[junit4:junit4]   2> 859 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51491
[junit4:junit4]   2> 860 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330001 with negotiated timeout 10000 for client /127.0.0.1:51491
[junit4:junit4]   2> 860 T1189 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330001, negotiated timeout = 10000
[junit4:junit4]   2> 860 T1190 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@564d9a9b name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 860 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 861 T1181 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 864 T1181 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 869 T1181 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 872 T1181 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 876 T1181 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> 877 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 884 T1181 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> 885 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 889 T1181 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> 890 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 898 T1181 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> 899 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 903 T1181 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> 903 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 907 T1181 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> 907 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 910 T1181 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> 914 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 928 T1181 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> 929 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 931 T1181 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> 932 T1181 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 935 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330001
[junit4:junit4]   2> 935 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51491 which had sessionid 0x13d8d0dd7330001
[junit4:junit4]   2> 935 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330001 closed
[junit4:junit4]   2> 936 T1190 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 1046 T1181 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 1087 T1181 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37166
[junit4:junit4]   2> 1088 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 1089 T1181 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 1089 T1181 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276
[junit4:junit4]   2> 1089 T1181 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/solr.xml
[junit4:junit4]   2> 1090 T1181 oasc.CoreContainer.<init> New CoreContainer 1689847368
[junit4:junit4]   2> 1090 T1181 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/'
[junit4:junit4]   2> 1090 T1181 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/'
[junit4:junit4]   2> 1109 T1181 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 1110 T1181 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 1110 T1181 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 1110 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 1110 T1181 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 1111 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 1111 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 1111 T1181 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 1111 T1181 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 1112 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 1118 T1181 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 1127 T1181 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38096/solr
[junit4:junit4]   2> 1127 T1181 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1127 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@40ef3ae2
[junit4:junit4]   2> 1128 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1128 T1200 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 1129 T1200 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 1129 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51492
[junit4:junit4]   2> 1130 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51492
[junit4:junit4]   2> 1130 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330002 with negotiated timeout 20000 for client /127.0.0.1:51492
[junit4:junit4]   2> 1130 T1200 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330002, negotiated timeout = 20000
[junit4:junit4]   2> 1131 T1201 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40ef3ae2 name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1131 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1132 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330002
[junit4:junit4]   2> 1133 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51492 which had sessionid 0x13d8d0dd7330002
[junit4:junit4]   2> 1133 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330002 closed
[junit4:junit4]   2> 1134 T1201 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 1134 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1137 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@37aae32d
[junit4:junit4]   2> 1139 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1139 T1202 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 1141 T1202 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 1141 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51493
[junit4:junit4]   2> 1142 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51493
[junit4:junit4]   2> 1143 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330003 with negotiated timeout 20000 for client /127.0.0.1:51493
[junit4:junit4]   2> 1143 T1202 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330003, negotiated timeout = 20000
[junit4:junit4]   2> 1144 T1203 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37aae32d name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1144 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1147 T1181 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 1149 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1150 T1181 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 1154 T1181 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 1156 T1181 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37166_
[junit4:junit4]   2> 1157 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:37166_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:37166_
[junit4:junit4]   2> 1157 T1181 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37166_
[junit4:junit4]   2> 1161 T1181 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 1167 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 1168 T1181 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 1171 T1181 oasc.Overseer.start Overseer (id=89382658201812995-127.0.0.1:37166_-n_0000000000) starting
[junit4:junit4]   2> 1172 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1173 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1174 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1175 T1181 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 1179 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1180 T1205 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 1180 T1181 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 1183 T1181 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 1184 T1181 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1186 T1204 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 1190 T1206 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/collection1
[junit4:junit4]   2> 1190 T1206 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 1190 T1206 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1191 T1206 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 1192 T1206 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/collection1/'
[junit4:junit4]   2> 1192 T1206 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/collection1/lib/README' to classloader
[junit4:junit4]   2> 1192 T1206 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1216 T1206 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1246 T1206 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1247 T1206 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 1251 T1206 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1630 T1206 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1636 T1206 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1638 T1206 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1648 T1206 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1653 T1206 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1657 T1206 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1658 T1206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1658 T1206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1658 T1206 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1659 T1206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1659 T1206 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1659 T1206 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1659 T1206 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363871128276/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/
[junit4:junit4]   2> 1660 T1206 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@558a7fb3
[junit4:junit4]   2> 1660 T1206 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1660 T1206 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data forceNew: false
[junit4:junit4]   2> 1660 T1206 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/index/
[junit4:junit4]   2> 1661 T1206 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1661 T1206 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/index forceNew: false
[junit4:junit4]   2> 1662 T1206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4b669d7c lockFactory=org.apache.lucene.store.NativeFSLockFactory@8c2ba6a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1662 T1206 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1664 T1206 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1664 T1206 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1665 T1206 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1665 T1206 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1666 T1206 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1666 T1206 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1666 T1206 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1667 T1206 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1667 T1206 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1670 T1206 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1672 T1206 oass.SolrIndexSearcher.<init> Opening Searcher@367522b8 main
[junit4:junit4]   2> 1672 T1206 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/tlog
[junit4:junit4]   2> 1672 T1206 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1673 T1206 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1675 T1207 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@367522b8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1676 T1206 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1676 T1206 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 2690 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2691 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37166",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37166_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 2691 T1204 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2691 T1204 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2695 T1203 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> 3678 T1206 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 3678 T1206 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37166 collection:control_collection shard:shard1
[junit4:junit4]   2> 3679 T1206 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 3684 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 3684 T1206 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 3685 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3686 T1206 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 3686 T1206 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 3687 T1206 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37166/collection1/
[junit4:junit4]   2> 3687 T1206 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 3687 T1206 oasc.SyncStrategy.syncToMe http://127.0.0.1:37166/collection1/ has no replicas
[junit4:junit4]   2> 3687 T1206 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37166/collection1/
[junit4:junit4]   2> 3687 T1206 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 3690 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4201 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4208 T1203 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> 4243 T1206 oasc.ZkController.register We are http://127.0.0.1:37166/collection1/ and leader is http://127.0.0.1:37166/collection1/
[junit4:junit4]   2> 4243 T1206 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37166
[junit4:junit4]   2> 4243 T1206 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 4244 T1206 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 4244 T1206 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 4246 T1206 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4247 T1181 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 4247 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 4248 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 4251 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 4252 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6392e862
[junit4:junit4]   2> 4252 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4253 T1209 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4253 T1209 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 4253 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51494
[junit4:junit4]   2> 4254 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51494
[junit4:junit4]   2> 4254 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330004 with negotiated timeout 10000 for client /127.0.0.1:51494
[junit4:junit4]   2> 4255 T1209 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330004, negotiated timeout = 10000
[junit4:junit4]   2> 4255 T1210 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6392e862 name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4255 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4257 T1181 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4259 T1181 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 4341 T1181 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 4343 T1181 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55486
[junit4:junit4]   2> 4344 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 4344 T1181 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 4344 T1181 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600
[junit4:junit4]   2> 4345 T1181 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/solr.xml
[junit4:junit4]   2> 4345 T1181 oasc.CoreContainer.<init> New CoreContainer 729517555
[junit4:junit4]   2> 4346 T1181 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/'
[junit4:junit4]   2> 4346 T1181 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/'
[junit4:junit4]   2> 4374 T1181 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 4375 T1181 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 4375 T1181 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 4376 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 4376 T1181 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 4377 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 4377 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 4378 T1181 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 4378 T1181 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 4379 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 4387 T1181 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4400 T1181 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38096/solr
[junit4:junit4]   2> 4401 T1181 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4401 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@7ccd71c2
[junit4:junit4]   2> 4402 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4402 T1220 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4403 T1220 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 4403 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51495
[junit4:junit4]   2> 4403 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51495
[junit4:junit4]   2> 4404 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330005 with negotiated timeout 20000 for client /127.0.0.1:51495
[junit4:junit4]   2> 4404 T1220 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330005, negotiated timeout = 20000
[junit4:junit4]   2> 4404 T1221 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ccd71c2 name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4404 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4406 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330005
[junit4:junit4]   2> 4406 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51495 which had sessionid 0x13d8d0dd7330005
[junit4:junit4]   2> 4406 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330005 closed
[junit4:junit4]   2> 4407 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 4407 T1221 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4409 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@67a578fe
[junit4:junit4]   2> 4411 T1222 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4411 T1222 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 4411 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4411 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51496
[junit4:junit4]   2> 4412 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51496
[junit4:junit4]   2> 4413 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330006 with negotiated timeout 20000 for client /127.0.0.1:51496
[junit4:junit4]   2> 4413 T1222 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330006, negotiated timeout = 20000
[junit4:junit4]   2> 4413 T1223 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@67a578fe name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4413 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4414 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4415 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4417 T1181 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 5425 T1181 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55486_
[junit4:junit4]   2> 5426 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:55486_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:55486_
[junit4:junit4]   2> 5427 T1181 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55486_
[junit4:junit4]   2> 5429 T1203 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 5430 T1210 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5430 T1223 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5431 T1203 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5437 T1224 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/collection1
[junit4:junit4]   2> 5437 T1224 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 5437 T1224 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 5438 T1224 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 5438 T1224 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/collection1/'
[junit4:junit4]   2> 5439 T1224 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/collection1/lib/README' to classloader
[junit4:junit4]   2> 5439 T1224 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 5473 T1224 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 5512 T1224 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 5513 T1224 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 5518 T1224 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 5920 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5921 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37166",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37166_",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37166__collection1"}
[junit4:junit4]   2> 5926 T1203 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> 5926 T1210 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> 5926 T1223 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> 6132 T1224 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 6137 T1224 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 6140 T1224 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 6150 T1224 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 6153 T1224 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 6157 T1224 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 6158 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 6158 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 6158 T1224 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 6159 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 6159 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 6160 T1224 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 6160 T1224 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/
[junit4:junit4]   2> 6160 T1224 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@558a7fb3
[junit4:junit4]   2> 6160 T1224 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 6161 T1224 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1 forceNew: false
[junit4:junit4]   2> 6161 T1224 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/index/
[junit4:junit4]   2> 6161 T1224 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 6162 T1224 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/index forceNew: false
[junit4:junit4]   2> 6163 T1224 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@481f34e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67aadddc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 6163 T1224 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 6165 T1224 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 6165 T1224 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 6166 T1224 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 6166 T1224 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 6167 T1224 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 6167 T1224 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 6167 T1224 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 6167 T1224 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 6168 T1224 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 6171 T1224 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 6174 T1224 oass.SolrIndexSearcher.<init> Opening Searcher@77cb7906 main
[junit4:junit4]   2> 6174 T1224 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/tlog
[junit4:junit4]   2> 6174 T1224 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 6175 T1224 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 6179 T1225 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77cb7906 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 6182 T1224 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 6182 T1224 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7429 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7430 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55486",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55486_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 7430 T1204 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 7430 T1204 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 7471 T1210 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> 7471 T1223 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> 7471 T1203 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> 8183 T1224 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 8183 T1224 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55486 collection:collection1 shard:shard1
[junit4:junit4]   2> 8184 T1224 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 8189 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:delete cxid:0x4a zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 8190 T1224 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 8190 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8192 T1224 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 8192 T1224 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 8192 T1224 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55486/collection1/
[junit4:junit4]   2> 8192 T1224 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 8193 T1224 oasc.SyncStrategy.syncToMe http://127.0.0.1:55486/collection1/ has no replicas
[junit4:junit4]   2> 8193 T1224 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55486/collection1/
[junit4:junit4]   2> 8193 T1224 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 8196 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8977 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8983 T1223 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> 8983 T1203 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> 8983 T1210 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> 9000 T1224 oasc.ZkController.register We are http://127.0.0.1:55486/collection1/ and leader is http://127.0.0.1:55486/collection1/
[junit4:junit4]   2> 9000 T1224 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55486
[junit4:junit4]   2> 9000 T1224 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 9001 T1224 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 9001 T1224 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9002 T1224 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9003 T1181 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 9004 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 9004 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 9095 T1181 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 9097 T1181 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54146
[junit4:junit4]   2> 9098 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 9098 T1181 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 9099 T1181 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348
[junit4:junit4]   2> 9099 T1181 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/solr.xml
[junit4:junit4]   2> 9099 T1181 oasc.CoreContainer.<init> New CoreContainer 374078220
[junit4:junit4]   2> 9100 T1181 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/'
[junit4:junit4]   2> 9100 T1181 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/'
[junit4:junit4]   2> 9117 T1181 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 9118 T1181 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 9118 T1181 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 9118 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 9119 T1181 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 9119 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 9119 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 9120 T1181 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 9120 T1181 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 9120 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 9126 T1181 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 9135 T1181 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38096/solr
[junit4:junit4]   2> 9135 T1181 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 9135 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@781b9b7b
[junit4:junit4]   2> 9136 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 9136 T1236 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 9137 T1236 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 9137 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51503
[junit4:junit4]   2> 9138 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51503
[junit4:junit4]   2> 9138 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330007 with negotiated timeout 20000 for client /127.0.0.1:51503
[junit4:junit4]   2> 9138 T1236 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330007, negotiated timeout = 20000
[junit4:junit4]   2> 9139 T1237 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@781b9b7b name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 9139 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 9140 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330007
[junit4:junit4]   2> 9140 T1237 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 9140 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51503 which had sessionid 0x13d8d0dd7330007
[junit4:junit4]   2> 9140 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330007 closed
[junit4:junit4]   2> 9141 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 9143 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4b8b826a
[junit4:junit4]   2> 9144 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 9144 T1238 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 9145 T1238 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 9145 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51504
[junit4:junit4]   2> 9145 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51504
[junit4:junit4]   2> 9146 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330008 with negotiated timeout 20000 for client /127.0.0.1:51504
[junit4:junit4]   2> 9146 T1238 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330008, negotiated timeout = 20000
[junit4:junit4]   2> 9146 T1239 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b8b826a name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 9146 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 9148 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9149 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9150 T1181 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 10153 T1181 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54146_
[junit4:junit4]   2> 10154 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:54146_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:54146_
[junit4:junit4]   2> 10154 T1181 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54146_
[junit4:junit4]   2> 10156 T1223 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> 10156 T1203 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> 10156 T1210 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> 10157 T1239 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10158 T1203 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10158 T1210 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10159 T1223 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10162 T1240 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/collection1
[junit4:junit4]   2> 10162 T1240 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 10163 T1240 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 10163 T1240 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 10164 T1240 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/collection1/'
[junit4:junit4]   2> 10164 T1240 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/collection1/lib/README' to classloader
[junit4:junit4]   2> 10164 T1240 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 10185 T1240 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 10210 T1240 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 10211 T1240 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 10214 T1240 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 10488 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10489 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55486",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55486_",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:55486__collection1"}
[junit4:junit4]   2> 10490 T1240 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 10492 T1203 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> 10492 T1223 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> 10492 T1239 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> 10492 T1210 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> 10496 T1240 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 10498 T1240 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 10509 T1240 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10512 T1240 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10516 T1240 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10517 T1240 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 10517 T1240 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 10517 T1240 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10518 T1240 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 10518 T1240 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 10518 T1240 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 10518 T1240 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363871136348/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty2/
[junit4:junit4]   2> 10519 T1240 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@558a7fb3
[junit4:junit4]   2> 10519 T1240 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 10519 T1240 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty2 forceNew: false
[junit4:junit4]   2> 10519 T1240 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty2/index/
[junit4:junit4]   2> 10520 T1240 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 10520 T1240 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty2/index forceNew: false
[junit4:junit4]   2> 10521 T1240 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@22bd74fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b4418cc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 10521 T1240 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 10523 T1240 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 10523 T1240 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 10523 T1240 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 10524 T1240 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 10524 T1240 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 10524 T1240 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 10525 T1240 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 10525 T1240 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 10525 T1240 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 10528 T1240 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 10531 T1240 oass.SolrIndexSearcher.<init> Opening Searcher@622d42c3 main
[junit4:junit4]   2> 10531 T1240 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty2/tlog
[junit4:junit4]   2> 10532 T1240 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 10532 T1240 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 10537 T1241 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@622d42c3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 10539 T1240 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 10539 T1240 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11995 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11996 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54146",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54146_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 11996 T1204 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 11996 T1204 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 11999 T1223 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> 11999 T1239 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> 11999 T1203 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> 11999 T1210 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> 12540 T1240 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 12541 T1240 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54146 collection:collection1 shard:shard2
[junit4:junit4]   2> 12541 T1240 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 12546 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 12546 T1240 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 12547 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12548 T1240 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 12549 T1240 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 12549 T1240 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54146/collection1/
[junit4:junit4]   2> 12549 T1240 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 12549 T1240 oasc.SyncStrategy.syncToMe http://127.0.0.1:54146/collection1/ has no replicas
[junit4:junit4]   2> 12549 T1240 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54146/collection1/
[junit4:junit4]   2> 12550 T1240 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 12552 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13503 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13510 T1239 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> 13510 T1203 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> 13510 T1223 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> 13511 T1210 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> 13556 T1240 oasc.ZkController.register We are http://127.0.0.1:54146/collection1/ and leader is http://127.0.0.1:54146/collection1/
[junit4:junit4]   2> 13556 T1240 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54146
[junit4:junit4]   2> 13556 T1240 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 13556 T1240 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 13557 T1240 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 13558 T1240 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13559 T1181 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 13560 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 13560 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13616 T1181 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 13618 T1181 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53442
[junit4:junit4]   2> 13619 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 13619 T1181 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 13619 T1181 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902
[junit4:junit4]   2> 13620 T1181 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/solr.xml
[junit4:junit4]   2> 13620 T1181 oasc.CoreContainer.<init> New CoreContainer 684543628
[junit4:junit4]   2> 13620 T1181 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/'
[junit4:junit4]   2> 13621 T1181 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/'
[junit4:junit4]   2> 13637 T1181 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 13637 T1181 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 13638 T1181 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 13638 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 13638 T1181 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 13638 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 13639 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 13639 T1181 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 13639 T1181 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 13639 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 13645 T1181 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 13653 T1181 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38096/solr
[junit4:junit4]   2> 13653 T1181 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 13654 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@74b889e4
[junit4:junit4]   2> 13654 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13655 T1252 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13655 T1252 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 13655 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51508
[junit4:junit4]   2> 13656 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51508
[junit4:junit4]   2> 13657 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd7330009 with negotiated timeout 20000 for client /127.0.0.1:51508
[junit4:junit4]   2> 13657 T1252 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd7330009, negotiated timeout = 20000
[junit4:junit4]   2> 13657 T1253 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74b889e4 name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13657 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13658 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330009
[junit4:junit4]   2> 13659 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51508 which had sessionid 0x13d8d0dd7330009
[junit4:junit4]   2> 13659 T1253 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 13659 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330009 closed
[junit4:junit4]   2> 13659 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 13662 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4e1c538f
[junit4:junit4]   2> 13662 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13662 T1254 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13663 T1254 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 13663 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51509
[junit4:junit4]   2> 13663 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51509
[junit4:junit4]   2> 13664 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd733000a with negotiated timeout 20000 for client /127.0.0.1:51509
[junit4:junit4]   2> 13664 T1254 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd733000a, negotiated timeout = 20000
[junit4:junit4]   2> 13664 T1255 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e1c538f name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13664 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13665 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13666 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13668 T1181 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 14670 T1181 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53442_
[junit4:junit4]   2> 14671 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:53442_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:53442_
[junit4:junit4]   2> 14671 T1181 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53442_
[junit4:junit4]   2> 14673 T1203 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> 14674 T1210 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14674 T1223 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14674 T1210 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> 14674 T1239 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14674 T1239 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> 14674 T1223 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> 14674 T1255 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14676 T1203 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14680 T1256 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/collection1
[junit4:junit4]   2> 14680 T1256 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 14680 T1256 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 14681 T1256 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 14682 T1256 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/collection1/'
[junit4:junit4]   2> 14682 T1256 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/collection1/lib/README' to classloader
[junit4:junit4]   2> 14682 T1256 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 14702 T1256 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 14736 T1256 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 14737 T1256 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 14742 T1256 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 15015 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15016 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54146",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54146_",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:54146__collection1"}
[junit4:junit4]   2> 15019 T1239 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> 15019 T1223 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> 15019 T1210 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> 15019 T1255 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> 15019 T1203 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> 15054 T1256 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 15059 T1256 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 15061 T1256 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 15069 T1256 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 15072 T1256 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 15075 T1256 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 15075 T1256 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 15076 T1256 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 15076 T1256 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 15076 T1256 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 15077 T1256 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 15077 T1256 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 15077 T1256 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363871140902/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3/
[junit4:junit4]   2> 15077 T1256 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@558a7fb3
[junit4:junit4]   2> 15078 T1256 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 15078 T1256 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3 forceNew: false
[junit4:junit4]   2> 15078 T1256 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3/index/
[junit4:junit4]   2> 15079 T1256 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 15079 T1256 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3/index forceNew: false
[junit4:junit4]   2> 15080 T1256 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@41bde33d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f48b6a2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 15080 T1256 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 15082 T1256 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 15082 T1256 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 15083 T1256 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 15083 T1256 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 15084 T1256 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 15084 T1256 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 15084 T1256 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 15085 T1256 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 15085 T1256 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 15088 T1256 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 15090 T1256 oass.SolrIndexSearcher.<init> Opening Searcher@548a997f main
[junit4:junit4]   2> 15090 T1256 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3/tlog
[junit4:junit4]   2> 15090 T1256 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 15091 T1256 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 15096 T1257 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@548a997f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 15098 T1256 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 15098 T1256 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16523 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16524 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53442",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53442_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 16524 T1204 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 16524 T1204 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 16527 T1210 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> 16527 T1223 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> 16527 T1239 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> 16527 T1255 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> 16527 T1203 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> 17100 T1256 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 17100 T1256 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53442 collection:collection1 shard:shard1
[junit4:junit4]   2> 17103 T1256 oasc.ZkController.register We are http://127.0.0.1:53442/collection1/ and leader is http://127.0.0.1:55486/collection1/
[junit4:junit4]   2> 17103 T1256 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53442
[junit4:junit4]   2> 17103 T1256 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 17104 T1256 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C97 name=collection1 org.apache.solr.core.SolrCore@2a1ec980 url=http://127.0.0.1:53442/collection1 node=127.0.0.1:53442_ C97_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, base_url=http://127.0.0.1:53442, node_name=127.0.0.1:53442_, state=down}
[junit4:junit4]   2> 17104 T1258 C97 P53442 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 17104 T1256 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17105 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 17105 T1258 C97 P53442 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 17106 T1258 C97 P53442 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 17106 T1181 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 17106 T1258 C97 P53442 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 17107 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 17107 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 17169 T1181 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 17171 T1181 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45797
[junit4:junit4]   2> 17172 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 17172 T1181 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 17172 T1181 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450
[junit4:junit4]   2> 17173 T1181 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/solr.xml
[junit4:junit4]   2> 17173 T1181 oasc.CoreContainer.<init> New CoreContainer 1614171621
[junit4:junit4]   2> 17173 T1181 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/'
[junit4:junit4]   2> 17173 T1181 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/'
[junit4:junit4]   2> 17189 T1181 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 17190 T1181 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 17190 T1181 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 17190 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 17191 T1181 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 17191 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 17191 T1181 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 17192 T1181 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 17192 T1181 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 17192 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 17197 T1181 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 17206 T1181 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38096/solr
[junit4:junit4]   2> 17206 T1181 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 17206 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1280c5d3
[junit4:junit4]   2> 17207 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 17208 T1269 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 17208 T1269 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 17208 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51525
[junit4:junit4]   2> 17209 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51525
[junit4:junit4]   2> 17209 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd733000b with negotiated timeout 20000 for client /127.0.0.1:51525
[junit4:junit4]   2> 17209 T1269 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd733000b, negotiated timeout = 20000
[junit4:junit4]   2> 17209 T1270 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1280c5d3 name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 17210 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 17211 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd733000b
[junit4:junit4]   2> 17211 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51525 which had sessionid 0x13d8d0dd733000b
[junit4:junit4]   2> 17211 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd733000b closed
[junit4:junit4]   2> 17212 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 17214 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@21e870e4
[junit4:junit4]   2> 17214 T1270 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 17215 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 17215 T1271 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 17215 T1271 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 17216 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51526
[junit4:junit4]   2> 17216 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51526
[junit4:junit4]   2> 17216 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd733000c with negotiated timeout 20000 for client /127.0.0.1:51526
[junit4:junit4]   2> 17216 T1271 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd733000c, negotiated timeout = 20000
[junit4:junit4]   2> 17217 T1272 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21e870e4 name:ZooKeeperConnection Watcher:127.0.0.1:38096/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 17217 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 17218 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 17219 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 17220 T1181 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 18034 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18035 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53442",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53442_",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:53442__collection1"}
[junit4:junit4]   2> 18039 T1210 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> 18039 T1223 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> 18039 T1255 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> 18040 T1203 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> 18039 T1239 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> 18039 T1272 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> 18110 T1216 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {core=collection1&checkLive=true&nodeName=127.0.0.1:53442_&version=2&onlyIfLeader=true&wt=javabin&action=PREPRECOVERY&coreNodeName=127.0.0.1:53442__collection1&state=recovering} status=0 QTime=1000 
[junit4:junit4]   2> 18222 T1181 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45797_
[junit4:junit4]   2> 18223 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:45797_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:45797_
[junit4:junit4]   2> 18224 T1181 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45797_
[junit4:junit4]   2> 18225 T1203 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> 18226 T1239 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> 18226 T1210 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> 18226 T1255 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18226 T1255 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> 18227 T1223 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18227 T1223 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> 18228 T1203 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18228 T1272 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18228 T1210 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18228 T1239 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18228 T1272 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> 18232 T1273 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/collection1
[junit4:junit4]   2> 18233 T1273 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 18233 T1273 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 18233 T1273 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 18234 T1273 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/collection1/'
[junit4:junit4]   2> 18235 T1273 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/collection1/lib/README' to classloader
[junit4:junit4]   2> 18235 T1273 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 18255 T1273 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 18281 T1273 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 18282 T1273 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 18285 T1273 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 18566 T1273 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 18571 T1273 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 18573 T1273 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 18582 T1273 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18584 T1273 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18586 T1273 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18587 T1273 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18587 T1273 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18587 T1273 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18588 T1273 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18588 T1273 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18588 T1273 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18589 T1273 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363871144450/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4/
[junit4:junit4]   2> 18589 T1273 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@558a7fb3
[junit4:junit4]   2> 18589 T1273 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18590 T1273 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4 forceNew: false
[junit4:junit4]   2> 18590 T1273 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4/index/
[junit4:junit4]   2> 18590 T1273 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 18590 T1273 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4/index forceNew: false
[junit4:junit4]   2> 18591 T1273 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e77cd12 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d99e865),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 18591 T1273 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 18593 T1273 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 18593 T1273 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 18593 T1273 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 18594 T1273 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 18594 T1273 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 18594 T1273 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 18595 T1273 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 18595 T1273 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 18595 T1273 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 18597 T1273 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 18599 T1273 oass.SolrIndexSearcher.<init> Opening Searcher@598cd7eb main
[junit4:junit4]   2> 18599 T1273 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4/tlog
[junit4:junit4]   2> 18600 T1273 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 18600 T1273 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 18603 T1274 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@598cd7eb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 18605 T1273 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 18605 T1273 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19543 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19544 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45797",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:45797_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 19544 T1204 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 19544 T1204 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 19548 T1210 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> 19548 T1255 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> 19548 T1203 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> 19548 T1272 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> 19548 T1239 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> 19548 T1223 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> 19607 T1273 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19608 T1273 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45797 collection:collection1 shard:shard2
[junit4:junit4]   2> 19611 T1273 oasc.ZkController.register We are http://127.0.0.1:45797/collection1/ and leader is http://127.0.0.1:54146/collection1/
[junit4:junit4]   2> 19611 T1273 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45797
[junit4:junit4]   2> 19611 T1273 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19611 T1273 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C98 name=collection1 org.apache.solr.core.SolrCore@5d108816 url=http://127.0.0.1:45797/collection1 node=127.0.0.1:45797_ C98_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, base_url=http://127.0.0.1:45797, node_name=127.0.0.1:45797_, state=down}
[junit4:junit4]   2> 19612 T1275 C98 P45797 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19612 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19613 T1275 C98 P45797 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19613 T1273 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19613 T1275 C98 P45797 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19614 T1275 C98 P45797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19614 T1181 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 19614 T1181 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19615 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19619 T1181 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19620 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19625 T1219 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/onenodecollectioncore
[junit4:junit4]   2> 19626 T1219 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19627 T1219 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19627 T1219 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19628 T1219 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19628 T1219 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19630 T1219 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19632 T1219 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/onenodecollectioncore/'
[junit4:junit4]   2> 19673 T1219 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 19720 T1219 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19721 T1219 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19727 T1219 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 20094 T1219 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 20099 T1219 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 20101 T1219 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2>  C97_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, base_url=http://127.0.0.1:53442, shard=shard1, node_name=127.0.0.1:53442_, state=recovering}
[junit4:junit4]   2> 20111 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55486/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 20111 T1258 C97 P53442 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53442 START replicas=[http://127.0.0.1:55486/collection1/] nUpdates=100
[junit4:junit4]   2> 20111 T1219 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 20112 T1258 C97 P53442 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 20112 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 20112 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 20112 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 20112 T1258 C97 P53442 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 20113 T1258 C97 P53442 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55486/collection1/. core=collection1
[junit4:junit4]   2> 20113 T1258 C97 P53442 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 20116 T1219 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> ASYNC  NEW_CORE C99 name=collection1 org.apache.solr.core.SolrCore@32e29dd2 url=http://127.0.0.1:55486/collection1 node=127.0.0.1:55486_ C99_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, base_url=http://127.0.0.1:55486, shard=shard1, node_name=127.0.0.1:55486_, state=active, leader=true}
[junit4:junit4]   2> 20118 T1216 C99 P55486 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 20119 T1217 C99 P55486 REQ /get {qt=/get&distrib=false&version=2&getVersions=100&wt=javabin} status=0 QTime=2 
[junit4:junit4]   2> 20120 T1216 C99 P55486 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@481f34e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67aadddc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 20121 T1219 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 20121 T1216 C99 P55486 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 20122 T1216 C99 P55486 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@481f34e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67aadddc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@481f34e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@67aadddc),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 20122 T1219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 20122 T1216 C99 P55486 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 20122 T1219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 20123 T1216 C99 P55486 oass.SolrIndexSearcher.<init> Opening Searcher@2f317fc3 realtime
[junit4:junit4]   2> 20123 T1219 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 20123 T1216 C99 P55486 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 20123 T1216 C99 P55486 /update {waitSearcher=true&version=2&commit_end_point=true&wt=javabin&openSearcher=false&commit=true&softCommit=false} {commit=} 0 5
[junit4:junit4]   2> 20124 T1258 C97 P53442 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 20124 T1258 C97 P53442 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 20125 T1219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 20125 T1219 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 20126 T1219 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 20126 T1219 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363871131600/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/
[junit4:junit4]   2> 20127 T1219 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@558a7fb3
[junit4:junit4]   2> 20128 T1219 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 20129 T1219 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection forceNew: false
[junit4:junit4]   2> 20129 T1219 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/index/
[junit4:junit4]   2> 20130 T1218 C99 P55486 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 20130 T1219 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 20130 T1218 C99 P55486 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=5 
[junit4:junit4]   2> 20130 T1219 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/index forceNew: false
[junit4:junit4]   2> 20131 T1258 C97 P53442 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 20131 T1258 C97 P53442 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 20131 T1258 C97 P53442 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 20132 T1219 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@108bc8fe lockFactory=org.apache.lucene.store.NativeFSLockFactory@2830e1f9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 20132 T1219 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 20133 T1216 C99 P55486 REQ /replication {qt=/replication&generation=2&version=2&command=filelist&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 20134 T1258 C97 P53442 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 20135 T1258 C97 P53442 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty3/index.20130321060547474 forceNew: false
[junit4:junit4]   2> 20135 T1219 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 20135 T1258 C97 P53442 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@151546c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e396b04) fullCopy=false
[junit4:junit4]   2> 20135 T1219 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 20136 T1219 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 20136 T1219 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 20137 T1219 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 20137 T1219 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 20137 T1217 C99 P55486 REQ /replication {file=segments_2&qt=/replication&checksum=true&generation=2&command=filecontent&wt=filestream} status=0 QTime=0 
[junit4:junit4]   2> 20137 T1219 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 20138 T1219 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 20138 T1258 C97 P53442 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 20138 T1219 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 20139 T1258 C97 P53442 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 20140 T1258 C97 P53442 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 20141 T1258 C97 P53442 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@41bde33d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f48b6a2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@41bde33d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f48b6a2),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 20141 T1258 C97 P53442 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 20142 T1258 C97 P53442 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 20142 T1258 C97 P53442 oass.SolrIndexSearcher.<init> Opening Searcher@710e2be3 main
[junit4:junit4]   2> 20142 T1219 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 20143 T1257 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@710e2be3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 20143 T1258 C97 P53442 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 20143 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 20144 T1258 C97 P53442 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 20144 T1258 C97 P53442 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 20145 T1258 C97 P53442 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 20145 T1219 oass.SolrIndexSearcher.<init> Opening Searcher@3043fa0a main
[junit4:junit4]   2> 20146 T1219 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/tlog
[junit4:junit4]   2> 20146 T1219 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 20147 T1219 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 20150 T1279 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@3043fa0a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 20152 T1219 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 21052 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21053 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45797",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:45797_",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:45797__collection1"}
[junit4:junit4]   2> 21055 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53442",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53442_",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:53442__collection1"}
[junit4:junit4]   2> 21058 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55486",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55486_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 21058 T1204 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 21058 T1204 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 21062 T1210 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> 21062 T1272 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> 21062 T1223 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> 21062 T1255 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> 21062 T1239 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> 21063 T1203 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> 21154 T1219 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 21154 T1219 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:55486 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 21155 T1219 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 21161 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:delete cxid:0xac zxid:0xc2 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 21161 T1219 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 21162 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21164 T1219 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 21164 T1219 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 21164 T1219 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55486/onenodecollectioncore/
[junit4:junit4]   2> 21165 T1219 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 21165 T1219 oasc.SyncStrategy.syncToMe http://127.0.0.1:55486/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 21165 T1219 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55486/onenodecollectioncore/
[junit4:junit4]   2> 21166 T1219 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 21168 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21620 T1232 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {core=collection1&checkLive=true&nodeName=127.0.0.1:45797_&version=2&onlyIfLeader=true&wt=javabin&action=PREPRECOVERY&coreNodeName=127.0.0.1:45797__collection1&state=recovering} status=0 QTime=2001 
[junit4:junit4]   2> 22569 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22575 T1255 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> 22575 T1239 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> 22575 T1210 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> 22575 T1223 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> 22575 T1203 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> 22575 T1272 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> 22624 T1219 oasc.ZkController.register We are http://127.0.0.1:55486/onenodecollectioncore/ and leader is http://127.0.0.1:55486/onenodecollectioncore/
[junit4:junit4]   2> 22624 T1219 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:55486
[junit4:junit4]   2> 22624 T1219 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 22624 T1219 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 22626 T1219 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22627 T1219 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection&version=2&name=onenodecollectioncore&roles=none&collection=onenodecollection&wt=javabin&action=CREATE&numShards=1} status=0 QTime=3002 
[junit4:junit4]   2> 22627 T1181 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 22628 T1181 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C98_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, base_url=http://127.0.0.1:45797, shard=shard2, node_name=127.0.0.1:45797_, state=recovering}
[junit4:junit4]   2> 23621 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54146/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 23621 T1275 C98 P45797 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45797 START replicas=[http://127.0.0.1:54146/collection1/] nUpdates=100
[junit4:junit4]   2> 23622 T1275 C98 P45797 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 23622 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 23622 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 23622 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 23622 T1275 C98 P45797 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 23623 T1275 C98 P45797 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54146/collection1/. core=collection1
[junit4:junit4]   2> 23623 T1275 C98 P45797 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C100 name=collection1 org.apache.solr.core.SolrCore@1ce040ea url=http://127.0.0.1:54146/collection1 node=127.0.0.1:54146_ C100_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, base_url=http://127.0.0.1:54146, shard=shard2, node_name=127.0.0.1:54146_, state=active, leader=true}
[junit4:junit4]   2> 23627 T1235 C100 P54146 REQ /get {qt=/get&distrib=false&version=2&getVersions=100&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 23628 T1233 C100 P54146 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 23629 T1181 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23631 T1233 C100 P54146 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@22bd74fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b4418cc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 23631 T1233 C100 P54146 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 23632 T1233 C100 P54146 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@22bd74fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b4418cc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@22bd74fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b4418cc),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23632 T1233 C100 P54146 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23633 T1233 C100 P54146 oass.SolrIndexSearcher.<init> Opening Searcher@1c63ff96 realtime
[junit4:junit4]   2> 23633 T1233 C100 P54146 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 23634 T1233 C100 P54146 /update {waitSearcher=true&version=2&commit_end_point=true&wt=javabin&openSearcher=false&commit=true&softCommit=false} {commit=} 0 6
[junit4:junit4]   2> 23635 T1275 C98 P45797 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23635 T1275 C98 P45797 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 23637 T1234 C100 P54146 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23638 T1234 C100 P54146 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1 
[junit4:junit4]   2> 23638 T1275 C98 P45797 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 23639 T1275 C98 P45797 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 23639 T1275 C98 P45797 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 23641 T1233 C100 P54146 REQ /replication {qt=/replication&generation=2&version=2&command=filelist&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 23642 T1275 C98 P45797 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 23643 T1275 C98 P45797 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty4/index.20130321060550982 forceNew: false
[junit4:junit4]   2> 23643 T1275 C98 P45797 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c2c8ef1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9177d39) fullCopy=false
[junit4:junit4]   2> 23646 T1232 C100 P54146 REQ /replication {file=segments_2&qt=/replication&checksum=true&generation=2&command=filecontent&wt=filestream} status=0 QTime=0 
[junit4:junit4]   2> 23647 T1275 C98 P45797 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 23648 T1275 C98 P45797 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 23649 T1275 C98 P45797 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 23650 T1275 C98 P45797 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e77cd12 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d99e865),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e77cd12 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d99e865),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23650 T1275 C98 P45797 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23651 T1275 C98 P45797 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 23651 T1275 C98 P45797 oass.SolrIndexSearcher.<init> Opening Searcher@576a466e main
[junit4:junit4]   2> 23652 T1274 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@576a466e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 23653 T1275 C98 P45797 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 23653 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 23653 T1275 C98 P45797 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 23653 T1275 C98 P45797 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 23654 T1275 C98 P45797 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 24083 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24084 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55486",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55486_",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:55486__onenodecollectioncore"}
[junit4:junit4]   2> 24086 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45797",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:45797_",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:45797__collection1"}
[junit4:junit4]   2> 24091 T1272 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> 24091 T1239 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> 24091 T1255 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> 24091 T1223 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> 24091 T1210 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> 24091 T1203 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> 24631 T1181 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24632 T1181 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 24633 T1181 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 24646 T1181 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38096 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@33310580
[junit4:junit4]   2> 24646 T1181 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 24647 T1282 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38096. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 24647 T1282 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38096, initiating session
[junit4:junit4]   2> 24647 T1183 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:51542
[junit4:junit4]   2> 24648 T1183 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:51542
[junit4:junit4]   2> 24649 T1185 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8d0dd733000d with negotiated timeout 10000 for client /127.0.0.1:51542
[junit4:junit4]   2> 24649 T1282 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38096, sessionid = 0x13d8d0dd733000d, negotiated timeout = 10000
[junit4:junit4]   2> 24649 T1283 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33310580 name:ZooKeeperConnection Watcher:127.0.0.1:38096 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 24649 T1181 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 24695 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd733000d
[junit4:junit4]   2> 24696 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51542 which had sessionid 0x13d8d0dd733000d
[junit4:junit4]   2> 24696 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd733000d closed
[junit4:junit4]   2> 24696 T1283 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 24697 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330004
[junit4:junit4]   2> 24697 T1210 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 24698 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51494 which had sessionid 0x13d8d0dd7330004
[junit4:junit4]   2> 24697 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330004 closed
[junit4:junit4]   2> 24699 T1181 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37166
[junit4:junit4]   2> 24700 T1181 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1689847368
[junit4:junit4]   2> 25597 T1204 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25598 T1204 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37166",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37166_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37166__collection1"}
[junit4:junit4]   2> 25600 T1272 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> 25600 T1223 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> 25600 T1239 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> 25600 T1203 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> 25601 T1255 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> 26701 T1181 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 26701 T1181 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 26704 T1181 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@2d229e0d
[junit4:junit4]   2> 26706 T1181 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> 26707 T1181 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 26707 T1181 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 26707 T1181 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 26708 T1181 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 26708 T1181 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/index
[junit4:junit4]   2> 26708 T1181 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data/index
[junit4:junit4]   2> 26709 T1181 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data
[junit4:junit4]   2> 26709 T1181 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/control/data
[junit4:junit4]   2> 26710 T1204 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89382658201812995-127.0.0.1:37166_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 26710 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330003
[junit4:junit4]   2> 26711 T1223 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> 26711 T1203 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> 26711 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51493 which had sessionid 0x13d8d0dd7330003
[junit4:junit4]   2> 26711 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330003 closed
[junit4:junit4]   2> 26711 T1203 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26712 T1203 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26712 T1239 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26712 T1272 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26712 T1203 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 26712 T1239 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> 26712 T1255 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26712 T1272 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> 26712 T1255 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> 26713 T1223 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26713 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:delete cxid:0xc9 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 26714 T1223 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 26716 T1223 oasc.Overseer.start Overseer (id=89382658201812998-127.0.0.1:55486_-n_0000000001) starting
[junit4:junit4]   2> 26716 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0xce zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26717 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0xcf zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26718 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0xd1 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26719 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330006 type:create cxid:0xd3 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26719 T1285 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 26720 T1284 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 26721 T1284 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 26722 T1284 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37166",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37166_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37166__collection1"}
[junit4:junit4]   2> 26725 T1272 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> 26725 T1239 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> 26725 T1255 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> 26725 T1223 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> 26733 T1181 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 26784 T1181 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 55486
[junit4:junit4]   2> 26785 T1181 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=729517555
[junit4:junit4]   2> 28229 T1284 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 28231 T1284 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55486",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55486_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:55486__onenodecollectioncore"}
[junit4:junit4]   2> 28236 T1284 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55486",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55486_",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:55486__collection1"}
[junit4:junit4]   2> 28242 T1255 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> 28242 T1223 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> 28243 T1272 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> 28243 T1239 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> 29787 T1181 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 29787 T1181 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 29789 T1181 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 29791 T1181 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@32e29dd2
[junit4:junit4]   2> 29795 T1181 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> 29795 T1181 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29796 T1181 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29796 T1181 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29798 T1181 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 29798 T1181 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/index
[junit4:junit4]   2> 29799 T1181 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1/index
[junit4:junit4]   2> 29799 T1181 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1
[junit4:junit4]   2> 29799 T1181 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363871127344/jetty1
[junit4:junit4]   2> 29800 T1181 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@22acab77
[junit4:junit4]   2> 29805 T1181 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> 29806 T1181 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29806 T1181 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29806 T1181 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29807 T1181 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 29808 T1181 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/index
[junit4:junit4]   2> 29808 T1181 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection/index
[junit4:junit4]   2> 29808 T1181 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection
[junit4:junit4]   2> 29809 T1181 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363871127344/onenodecollection
[junit4:junit4]   2> 29810 T1284 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89382658201812998-127.0.0.1:55486_-n_0000000001) am no longer a leader.
[junit4:junit4]   2> 29810 T1186 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8d0dd7330006
[junit4:junit4]   2> 29811 T1223 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> 29811 T1239 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> 29811 T1183 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d8d0dd7330006, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 29811 T1272 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> 29811 T1181 oaz.ZooKeeper.close Session: 0x13d8d0dd7330006 closed
[junit4:junit4]   2> 29811 T1183 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:51496 which had sessionid 0x13d8d0dd7330006
[junit4:junit4]   2> 29811 T1223 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 29812 T1223 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 29812 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000a type:delete cxid:0x5e zxid:0xf9 txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 29812 T1223 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 29812 T1255 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 29813 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd733000a type:create cxid:0x5f zxid:0xfa txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29813 T1272 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29813 T1239 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29814 T1186 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8d0dd7330008 type:delete cxid:0x7f zxid:0xfc txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 29814 T1255 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4]   2> 29814 T1255 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4]   2> 29815 T1255 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 29815 T1239 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 29815 T1255 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53442/collection1/
[junit4:junit4]   2> 29815 T1255 oasu.PeerSync.sync PeerS

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

xception: Server at http://127.0.0.1:54146/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([DD0A1818EB265ACD:5CEC96009C793AF1]: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> 33235 T1181 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 33239 T1180 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> 33297 T1255 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33297 T1255 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> 33297 T1255 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33297 T1255 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 33660 T1184 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> NOTE: test params are: codec=Asserting, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=be_BY, timezone=MST
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=2,free=105239184,total=335609856
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestAtomicUpdateErrorCases, EchoParamsTest, TestLMJelinekMercerSimilarityFactory, HighlighterConfigTest, CurrencyFieldOpenExchangeTest, OutputWriterTest, UniqFieldsUpdateProcessorFactoryTest, TestDistributedSearch, DisMaxRequestHandlerTest, TestDFRSimilarityFactory, DebugComponentTest, TestNumberUtils, SolrCoreCheckLockOnStartupTest, TestElisionMultitermQuery, DOMUtilTest, TestMergePolicyConfig, TestCopyFieldCollectionResource, DocumentAnalysisRequestHandlerTest, TestPartialUpdateDeduplication, TestUtils, TestReload, TestStressLucene, TestFastOutputStream, FieldAnalysisRequestHandlerTest, TestSolrXMLSerializer, TestCSVResponseWriter, RequiredFieldsTest, TestCSVLoader, TestBM25SimilarityFactory, XmlUpdateRequestHandlerTest, TestFoldingMultitermQuery, TestSolr4Spatial, TestOmitPositions, BadIndexSchemaTest, SolrCmdDistributorTest, ZkSolrClientTest, CurrencyFieldXmlFileTest, HighlighterTest, IndexSchemaRuntimeFieldTest, SortByFunctionTest, SignatureUpdateProcessorFactoryTest, StatsComponentTest, SuggesterWFSTTest, ConvertedLegacyTest, DefaultValueUpdateProcessorTest, SpellCheckComponentTest, TestSystemIdResolver, TestFiltering, TestIndexingPerformance, TestArbitraryIndexDir, NotRequiredUniqueKeyTest, NoCacheHeaderTest, SolrPluginUtilsTest, TestCollationField, TestBinaryResponseWriter, DateMathParserTest, FullSolrCloudDistribCmdsTest, TestPropInject, TestLuceneMatchVersion, TestFieldTypeResource, TestFieldTypeCollectionResource, TestJmxIntegration, TestQuerySenderNoQuery, UpdateParamsTest, TestSolrJ, XsltUpdateRequestHandlerTest, ChaosMonkeySafeLeaderTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 33.76s, 1 test, 1 error <<< FAILURES!

[...truncated 456 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:375: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:355: 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:1210: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:874: There were test failures: 272 suites, 1144 tests, 1 error, 13 ignored (7 assumptions)

Total time: 36 minutes 31 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.8.0-ea-b79 -XX:+UseParallelGC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message