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-MacOSX (64bit/jdk1.7.0) - Build # 217 - Failure!
Date Tue, 12 Feb 2013 17:50:37 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/217/
Java: 64bit/jdk1.7.0 -XX:+UseSerialGC

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

Error Message:
Captured an uncaught exception in thread: Thread[id=2920, name=testExecutor-1435-thread-10, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]

Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=2920, name=testExecutor-1435-thread-10, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
Caused by: java.lang.RuntimeException: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:49861/_p/ic
	at __randomizedtesting.SeedInfo.seed([71DF31F42561CAC2]:0)
	at org.apache.solr.cloud.BasicDistributedZkTest$2.run(BasicDistributedZkTest.java:722)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)
Caused by: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:49861/_p/ic
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:416)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.cloud.BasicDistributedZkTest$2.run(BasicDistributedZkTest.java:720)
	... 3 more
Caused by: java.net.SocketException: Invalid argument
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:150)
	at java.net.SocketInputStream.read(SocketInputStream.java:121)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:149)
	at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:111)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:264)
	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:98)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:252)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:282)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:247)
	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:216)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:298)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:647)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
	... 5 more




Build Log:
[...truncated 9067 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4]   2> 0 T2586 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_p/ic
[junit4:junit4]   2> 7 T2586 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZkTest-1360690445376
[junit4:junit4]   2> 8 T2586 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 9 T2587 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 10 T2587 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 11 T2587 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 11 T2587 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 12 T2587 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 13 T2587 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 112 T2586 oasc.ZkTestServer.run start zk server on port:49848
[junit4:junit4]   2> 113 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@43ffa564
[junit4:junit4]   2> 115 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 116 T2592 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 116 T2592 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 117 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49849
[junit4:junit4]   2> 117 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49849
[junit4:junit4]   2> 118 T2590 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 121 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460000 with negotiated timeout 10000 for client /127.0.0.1:49849
[junit4:junit4]   2> 121 T2592 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460000, negotiated timeout = 10000
[junit4:junit4]   2> 122 T2593 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43ffa564 name:ZooKeeperConnection Watcher:127.0.0.1:49848 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 122 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 123 T2586 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 127 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c460000
[junit4:junit4]   2> 128 T2593 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 128 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c460000 closed
[junit4:junit4]   2> 129 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49849 which had sessionid 0x13ccf787c460000
[junit4:junit4]   2> 130 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@12b65ff6
[junit4:junit4]   2> 131 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 131 T2594 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 132 T2594 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 132 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49850
[junit4:junit4]   2> 133 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49850
[junit4:junit4]   2> 134 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460001 with negotiated timeout 10000 for client /127.0.0.1:49850
[junit4:junit4]   2> 134 T2594 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460001, negotiated timeout = 10000
[junit4:junit4]   2> 135 T2595 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12b65ff6 name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 135 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 135 T2586 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 142 T2586 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 147 T2586 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 151 T2586 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 156 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 157 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 171 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 173 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 179 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 181 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 187 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 188 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 194 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 195 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 201 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 202 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 209 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 210 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 215 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 216 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 222 T2586 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 223 T2586 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 228 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c460001
[junit4:junit4]   2> 229 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49850 which had sessionid 0x13ccf787c460001
[junit4:junit4]   2> 229 T2595 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 229 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c460001 closed
[junit4:junit4]   2> 440 T2586 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 554 T2586 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49851
[junit4:junit4]   2> 555 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 556 T2586 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 557 T2586 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599
[junit4:junit4]   2> 557 T2586 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/solr.xml
[junit4:junit4]   2> 558 T2586 oasc.CoreContainer.<init> New CoreContainer 282142958
[junit4:junit4]   2> 559 T2586 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/'
[junit4:junit4]   2> 559 T2586 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/'
[junit4:junit4]   2> 598 T2586 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 599 T2586 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 600 T2586 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 600 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 601 T2586 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 601 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 602 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 602 T2586 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 603 T2586 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 603 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 617 T2586 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 636 T2586 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49848/solr
[junit4:junit4]   2> 636 T2586 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 637 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3b14a23
[junit4:junit4]   2> 638 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 639 T2605 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 641 T2605 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 641 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49852
[junit4:junit4]   2> 642 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49852
[junit4:junit4]   2> 643 T2605 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460002, negotiated timeout = 20000
[junit4:junit4]   2> 643 T2606 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b14a23 name:ZooKeeperConnection Watcher:127.0.0.1:49848 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 644 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 645 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460002 with negotiated timeout 20000 for client /127.0.0.1:49852
[junit4:junit4]   2> 646 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c460002
[junit4:junit4]   2> 647 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49852 which had sessionid 0x13ccf787c460002
[junit4:junit4]   2> 648 T2606 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 648 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c460002 closed
[junit4:junit4]   2> 649 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 657 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@381cd156
[junit4:junit4]   2> 658 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 659 T2607 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 660 T2607 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 660 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49853
[junit4:junit4]   2> 661 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49853
[junit4:junit4]   2> 662 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460003 with negotiated timeout 20000 for client /127.0.0.1:49853
[junit4:junit4]   2> 662 T2607 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460003, negotiated timeout = 20000
[junit4:junit4]   2> 663 T2608 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@381cd156 name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 663 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 666 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 668 T2586 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 672 T2586 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49851__p%2Fic
[junit4:junit4]   2> 673 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49851__p%2Fic Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49851__p%2Fic
[junit4:junit4]   2> 674 T2586 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49851__p%2Fic
[junit4:junit4]   2> 686 T2586 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 693 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 694 T2586 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 699 T2586 oasc.Overseer.start Overseer (id=89174209028554755-127.0.0.1:49851__p%2Fic-n_0000000000) starting
[junit4:junit4]   2> 700 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 702 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 704 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 707 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 708 T2610 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 711 T2586 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 716 T2586 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 720 T2609 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 727 T2611 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/collection1
[junit4:junit4]   2> 727 T2611 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 729 T2611 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 729 T2611 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 731 T2611 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/collection1/'
[junit4:junit4]   2> 732 T2611 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 733 T2611 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/collection1/lib/README' to classloader
[junit4:junit4]   2> 811 T2611 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 869 T2611 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 870 T2611 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 875 T2611 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1473 T2611 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1482 T2611 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1485 T2611 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1510 T2611 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1515 T2611 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1522 T2611 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1524 T2611 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1526 T2611 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360690445599/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/
[junit4:junit4]   2> 1526 T2611 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d2790
[junit4:junit4]   2> 1527 T2611 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 1528 T2611 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data forceNew:false
[junit4:junit4]   2> 1528 T2611 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data
[junit4:junit4]   2> 1529 T2611 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/index/
[junit4:junit4]   2> 1529 T2611 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1531 T2611 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/index forceNew:false
[junit4:junit4]   2> 1537 T2611 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@139000ea),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1537 T2611 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1538 T2611 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/index
[junit4:junit4]   2> 1538 T2611 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 1541 T2611 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1553 T2611 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 1554 T2611 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1554 T2611 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 1555 T2611 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1556 T2611 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1556 T2611 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1557 T2611 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1558 T2611 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1558 T2611 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 1559 T2611 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 1560 T2611 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1560 T2611 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 1561 T2611 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 1561 T2611 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 1562 T2611 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1562 T2611 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1563 T2611 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1564 T2611 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1564 T2611 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1565 T2611 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1566 T2611 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1566 T2611 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1567 T2611 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1568 T2611 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 1568 T2611 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 1575 T2611 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1579 T2611 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 1581 T2611 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 1584 T2611 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data
[junit4:junit4]   2> 1586 T2611 oass.SolrIndexSearcher.<init> Opening Searcher@395919b4 main
[junit4:junit4]   2> 1588 T2611 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1588 T2611 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1589 T2611 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 1598 T2611 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 1633 T2612 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@395919b4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1642 T2611 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1642 T2611 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1643 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x51 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 2230 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2231 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49851__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49851/_p/ic"}
[junit4:junit4]   2> 2232 T2609 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2232 T2609 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2233 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x59 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 2240 T2608 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> 2649 T2611 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2649 T2611 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49851/_p/ic collection:control_collection shard:shard1
[junit4:junit4]   2> 2651 T2611 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2662 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:delete cxid:0x73 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 2663 T2611 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2664 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x74 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2667 T2611 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2667 T2611 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2667 T2611 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49851/_p/ic/collection1/
[junit4:junit4]   2> 2668 T2611 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2668 T2611 oasc.SyncStrategy.syncToMe http://127.0.0.1:49851/_p/ic/collection1/ has no replicas
[junit4:junit4]   2> 2668 T2611 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49851/_p/ic/collection1/
[junit4:junit4]   2> 2669 T2611 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2676 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460003 type:create cxid:0x7e zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3751 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3768 T2608 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> 3811 T2611 oasc.ZkController.register We are http://127.0.0.1:49851/_p/ic/collection1/ and leader is http://127.0.0.1:49851/_p/ic/collection1/
[junit4:junit4]   2> 3812 T2611 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49851/_p/ic
[junit4:junit4]   2> 3812 T2611 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3813 T2611 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3813 T2611 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3816 T2611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3819 T2586 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 3820 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3821 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3832 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3838 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@181bcfe6
[junit4:junit4]   2> 3839 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3840 T2613 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3840 T2613 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 3841 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49854
[junit4:junit4]   2> 3841 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49854
[junit4:junit4]   2> 3842 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460004 with negotiated timeout 10000 for client /127.0.0.1:49854
[junit4:junit4]   2> 3843 T2613 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460004, negotiated timeout = 10000
[junit4:junit4]   2> 3843 T2614 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@181bcfe6 name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3843 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3845 T2586 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3847 T2586 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 4034 T2586 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 4038 T2586 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49855
[junit4:junit4]   2> 4041 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 4041 T2586 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 4042 T2586 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216
[junit4:junit4]   2> 4042 T2586 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/solr.xml
[junit4:junit4]   2> 4042 T2586 oasc.CoreContainer.<init> New CoreContainer 2056500761
[junit4:junit4]   2> 4043 T2586 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/'
[junit4:junit4]   2> 4043 T2586 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/'
[junit4:junit4]   2> 4088 T2586 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 4089 T2586 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 4090 T2586 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 4092 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 4092 T2586 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 4093 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 4094 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 4095 T2586 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 4096 T2586 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 4097 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 4119 T2586 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4139 T2586 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49848/solr
[junit4:junit4]   2> 4140 T2586 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4141 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@669901c6
[junit4:junit4]   2> 4142 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4142 T2624 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4144 T2624 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 4144 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49856
[junit4:junit4]   2> 4145 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49856
[junit4:junit4]   2> 4146 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460005 with negotiated timeout 20000 for client /127.0.0.1:49856
[junit4:junit4]   2> 4147 T2624 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460005, negotiated timeout = 20000
[junit4:junit4]   2> 4147 T2625 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@669901c6 name:ZooKeeperConnection Watcher:127.0.0.1:49848 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4148 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4150 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c460005
[junit4:junit4]   2> 4151 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49856 which had sessionid 0x13ccf787c460005
[junit4:junit4]   2> 4151 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c460005 closed
[junit4:junit4]   2> 4151 T2625 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4152 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 4159 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@a6a783e
[junit4:junit4]   2> 4160 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4161 T2626 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4162 T2626 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 4162 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49857
[junit4:junit4]   2> 4163 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49857
[junit4:junit4]   2> 4164 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460006 with negotiated timeout 20000 for client /127.0.0.1:49857
[junit4:junit4]   2> 4164 T2626 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460006, negotiated timeout = 20000
[junit4:junit4]   2> 4165 T2627 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a6a783e name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4168 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4172 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4175 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4178 T2586 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4183 T2586 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49855__p%2Fic
[junit4:junit4]   2> 4184 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49855__p%2Fic Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49855__p%2Fic
[junit4:junit4]   2> 4186 T2586 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49855__p%2Fic
[junit4:junit4]   2> 4190 T2608 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> 4192 T2627 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4192 T2614 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4194 T2608 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4203 T2628 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/collection1
[junit4:junit4]   2> 4203 T2628 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4205 T2628 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4205 T2628 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4207 T2628 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/collection1/'
[junit4:junit4]   2> 4208 T2628 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4209 T2628 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/collection1/lib/README' to classloader
[junit4:junit4]   2> 4261 T2628 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4338 T2628 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4340 T2628 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4347 T2628 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4970 T2628 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4981 T2628 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4985 T2628 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5012 T2628 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5018 T2628 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5026 T2628 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5028 T2628 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5034 T2628 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360690449216/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/
[junit4:junit4]   2> 5035 T2628 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d2790
[junit4:junit4]   2> 5036 T2628 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 5037 T2628 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1 forceNew:false
[junit4:junit4]   2> 5037 T2628 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1
[junit4:junit4]   2> 5038 T2628 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index/
[junit4:junit4]   2> 5038 T2628 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5039 T2628 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index forceNew:false
[junit4:junit4]   2> 5045 T2628 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@260f6592),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5045 T2628 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5046 T2628 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index
[junit4:junit4]   2> 5046 T2628 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 5049 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5049 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 5050 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5050 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 5051 T2628 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5051 T2628 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5052 T2628 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5053 T2628 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5054 T2628 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5054 T2628 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 5055 T2628 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 5055 T2628 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5056 T2628 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 5056 T2628 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 5057 T2628 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 5058 T2628 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5059 T2628 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5060 T2628 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5060 T2628 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5061 T2628 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5062 T2628 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5062 T2628 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5063 T2628 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5064 T2628 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5065 T2628 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 5065 T2628 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 5073 T2628 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5077 T2628 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 5079 T2628 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 5082 T2628 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1
[junit4:junit4]   2> 5083 T2628 oass.SolrIndexSearcher.<init> Opening Searcher@1d7812ee main
[junit4:junit4]   2> 5084 T2628 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5084 T2628 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5085 T2628 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 5090 T2628 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 5122 T2629 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d7812ee main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5130 T2628 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5130 T2628 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 5279 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5280 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49851__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49851/_p/ic"}
[junit4:junit4]   2> 5289 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49855__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49855/_p/ic"}
[junit4:junit4]   2> 5289 T2609 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 5289 T2609 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 5298 T2627 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> 5298 T2614 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> 5298 T2608 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> 6134 T2628 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 6134 T2628 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49855/_p/ic collection:collection1 shard:shard1
[junit4:junit4]   2> 6135 T2628 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 6146 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460006 type:delete cxid:0x45 zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 6148 T2628 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 6148 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460006 type:create cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6152 T2628 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 6152 T2628 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 6152 T2628 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49855/_p/ic/collection1/
[junit4:junit4]   2> 6152 T2628 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 6153 T2628 oasc.SyncStrategy.syncToMe http://127.0.0.1:49855/_p/ic/collection1/ has no replicas
[junit4:junit4]   2> 6153 T2628 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49855/_p/ic/collection1/
[junit4:junit4]   2> 6153 T2628 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 6163 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460006 type:create cxid:0x50 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6815 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6840 T2608 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> 6840 T2614 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> 6841 T2627 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> 6887 T2628 oasc.ZkController.register We are http://127.0.0.1:49855/_p/ic/collection1/ and leader is http://127.0.0.1:49855/_p/ic/collection1/
[junit4:junit4]   2> 6888 T2628 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49855/_p/ic
[junit4:junit4]   2> 6888 T2628 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 6888 T2628 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 6888 T2628 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6891 T2628 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6893 T2586 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 6893 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 6894 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 7084 T2586 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 7087 T2586 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49858
[junit4:junit4]   2> 7089 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 7090 T2586 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 7090 T2586 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268
[junit4:junit4]   2> 7091 T2586 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/solr.xml
[junit4:junit4]   2> 7091 T2586 oasc.CoreContainer.<init> New CoreContainer 229198843
[junit4:junit4]   2> 7092 T2586 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/'
[junit4:junit4]   2> 7092 T2586 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/'
[junit4:junit4]   2> 7134 T2586 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 7135 T2586 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 7135 T2586 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 7136 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 7137 T2586 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 7138 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 7139 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 7139 T2586 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 7140 T2586 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 7141 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 7154 T2586 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 7173 T2586 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49848/solr
[junit4:junit4]   2> 7174 T2586 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 7174 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2fb7b2ea
[junit4:junit4]   2> 7176 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 7176 T2639 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 7177 T2639 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 7178 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49859
[junit4:junit4]   2> 7178 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49859
[junit4:junit4]   2> 7180 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460007 with negotiated timeout 20000 for client /127.0.0.1:49859
[junit4:junit4]   2> 7180 T2639 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460007, negotiated timeout = 20000
[junit4:junit4]   2> 7181 T2640 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fb7b2ea name:ZooKeeperConnection Watcher:127.0.0.1:49848 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 7181 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 7183 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c460007
[junit4:junit4]   2> 7184 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49859 which had sessionid 0x13ccf787c460007
[junit4:junit4]   2> 7185 T2640 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 7184 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c460007 closed
[junit4:junit4]   2> 7186 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 7190 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7c0e4865
[junit4:junit4]   2> 7191 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 7192 T2641 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 7193 T2641 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 7193 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49860
[junit4:junit4]   2> 7194 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49860
[junit4:junit4]   2> 7195 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460008 with negotiated timeout 20000 for client /127.0.0.1:49860
[junit4:junit4]   2> 7195 T2641 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460008, negotiated timeout = 20000
[junit4:junit4]   2> 7196 T2642 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c0e4865 name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 7196 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 7197 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7199 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460008 type:create cxid:0x2 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7202 T2586 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 7207 T2586 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49858__p%2Fic
[junit4:junit4]   2> 7208 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460008 type:delete cxid:0x9 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49858__p%2Fic Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49858__p%2Fic
[junit4:junit4]   2> 7209 T2586 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49858__p%2Fic
[junit4:junit4]   2> 7213 T2627 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> 7214 T2614 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> 7214 T2608 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> 7216 T2642 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7218 T2627 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7219 T2608 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7220 T2614 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7235 T2643 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/collection1
[junit4:junit4]   2> 7236 T2643 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 7237 T2643 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 7237 T2643 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 7240 T2643 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/collection1/'
[junit4:junit4]   2> 7242 T2643 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 7242 T2643 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/collection1/lib/README' to classloader
[junit4:junit4]   2> 7303 T2643 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 7390 T2643 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 7392 T2643 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 7398 T2643 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 7999 T2643 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 8005 T2643 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 8008 T2643 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 8028 T2643 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 8034 T2643 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 8041 T2643 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 8044 T2643 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 8047 T2643 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360690452268/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/
[junit4:junit4]   2> 8048 T2643 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d2790
[junit4:junit4]   2> 8049 T2643 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 8051 T2643 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2 forceNew:false
[junit4:junit4]   2> 8052 T2643 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2
[junit4:junit4]   2> 8052 T2643 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index/
[junit4:junit4]   2> 8053 T2643 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 8054 T2643 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index forceNew:false
[junit4:junit4]   2> 8059 T2643 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b021bb9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 8059 T2643 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 8060 T2643 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index
[junit4:junit4]   2> 8060 T2643 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 8063 T2643 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 8063 T2643 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 8063 T2643 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 8064 T2643 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 8065 T2643 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 8066 T2643 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 8067 T2643 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 8069 T2643 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 8070 T2643 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 8071 T2643 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 8071 T2643 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 8072 T2643 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 8073 T2643 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 8073 T2643 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 8073 T2643 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 8074 T2643 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 8075 T2643 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8076 T2643 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8076 T2643 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8077 T2643 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8077 T2643 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8078 T2643 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8079 T2643 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8079 T2643 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8080 T2643 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 8081 T2643 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 8087 T2643 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 8091 T2643 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 8093 T2643 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 8096 T2643 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2
[junit4:junit4]   2> 8098 T2643 oass.SolrIndexSearcher.<init> Opening Searcher@6a956af7 main
[junit4:junit4]   2> 8099 T2643 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 8099 T2643 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 8099 T2643 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 8106 T2643 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 8131 T2644 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a956af7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 8136 T2643 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 8136 T2643 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8353 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8354 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49855__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49855/_p/ic"}
[junit4:junit4]   2> 8361 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49858__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49858/_p/ic"}
[junit4:junit4]   2> 8362 T2609 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 8362 T2609 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 8371 T2608 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> 8371 T2642 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> 8372 T2627 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> 8371 T2614 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> 9139 T2643 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 9140 T2643 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49858/_p/ic collection:collection1 shard:shard2
[junit4:junit4]   2> 9143 T2643 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 9160 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460008 type:delete cxid:0x44 zxid:0x7c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 9161 T2643 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 9162 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460008 type:create cxid:0x45 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9166 T2643 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 9167 T2643 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 9167 T2643 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49858/_p/ic/collection1/
[junit4:junit4]   2> 9168 T2643 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 9168 T2643 oasc.SyncStrategy.syncToMe http://127.0.0.1:49858/_p/ic/collection1/ has no replicas
[junit4:junit4]   2> 9169 T2643 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49858/_p/ic/collection1/
[junit4:junit4]   2> 9169 T2643 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 9175 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c460008 type:create cxid:0x4e zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9883 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9895 T2614 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> 9895 T2642 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> 9895 T2608 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> 9895 T2627 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> 9951 T2643 oasc.ZkController.register We are http://127.0.0.1:49858/_p/ic/collection1/ and leader is http://127.0.0.1:49858/_p/ic/collection1/
[junit4:junit4]   2> 9951 T2643 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49858/_p/ic
[junit4:junit4]   2> 9952 T2643 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 9952 T2643 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 9952 T2643 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9955 T2643 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9957 T2586 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 9957 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 9958 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 10124 T2586 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 10128 T2586 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49861
[junit4:junit4]   2> 10129 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 10130 T2586 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 10130 T2586 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333
[junit4:junit4]   2> 10131 T2586 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/solr.xml
[junit4:junit4]   2> 10131 T2586 oasc.CoreContainer.<init> New CoreContainer 1537734339
[junit4:junit4]   2> 10132 T2586 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/'
[junit4:junit4]   2> 10133 T2586 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/'
[junit4:junit4]   2> 10170 T2586 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 10170 T2586 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 10171 T2586 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 10171 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 10172 T2586 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 10173 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 10173 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 10174 T2586 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 10174 T2586 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 10175 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 10188 T2586 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 10223 T2586 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49848/solr
[junit4:junit4]   2> 10223 T2586 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 10224 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@234e803c
[junit4:junit4]   2> 10226 T2654 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 10225 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 10227 T2654 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 10227 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49862
[junit4:junit4]   2> 10228 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49862
[junit4:junit4]   2> 10230 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c460009 with negotiated timeout 20000 for client /127.0.0.1:49862
[junit4:junit4]   2> 10230 T2654 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c460009, negotiated timeout = 20000
[junit4:junit4]   2> 10230 T2655 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@234e803c name:ZooKeeperConnection Watcher:127.0.0.1:49848 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 10231 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 10233 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c460009
[junit4:junit4]   2> 10234 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49862 which had sessionid 0x13ccf787c460009
[junit4:junit4]   2> 10234 T2655 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 10234 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c460009 closed
[junit4:junit4]   2> 10236 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 10241 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@468562bb
[junit4:junit4]   2> 10243 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 10243 T2656 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 10244 T2656 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 10245 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49863
[junit4:junit4]   2> 10245 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49863
[junit4:junit4]   2> 10246 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c46000a with negotiated timeout 20000 for client /127.0.0.1:49863
[junit4:junit4]   2> 10246 T2656 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c46000a, negotiated timeout = 20000
[junit4:junit4]   2> 10247 T2657 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@468562bb name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 10247 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 10249 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c46000a type:create cxid:0x1 zxid:0x8d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 10250 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c46000a type:create cxid:0x2 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 10253 T2586 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 10257 T2586 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49861__p%2Fic
[junit4:junit4]   2> 10258 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c46000a type:delete cxid:0x9 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49861__p%2Fic Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49861__p%2Fic
[junit4:junit4]   2> 10259 T2586 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49861__p%2Fic
[junit4:junit4]   2> 10262 T2614 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> 10262 T2608 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> 10263 T2642 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> 10263 T2627 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> 10264 T2657 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 10267 T2614 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 10267 T2608 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 10268 T2642 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 10269 T2627 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 10279 T2658 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/collection1
[junit4:junit4]   2> 10279 T2658 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 10280 T2658 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 10281 T2658 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 10283 T2658 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/collection1/'
[junit4:junit4]   2> 10284 T2658 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 10284 T2658 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/collection1/lib/README' to classloader
[junit4:junit4]   2> 10346 T2658 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 10421 T2658 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 10422 T2658 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 10429 T2658 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 11025 T2658 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 11037 T2658 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 11041 T2658 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 11060 T2658 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 11065 T2658 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 11070 T2658 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 11072 T2658 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 11074 T2658 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360690455333/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/
[junit4:junit4]   2> 11074 T2658 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d2790
[junit4:junit4]   2> 11075 T2658 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 11075 T2658 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3 forceNew:false
[junit4:junit4]   2> 11076 T2658 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 11076 T2658 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index/
[junit4:junit4]   2> 11076 T2658 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 11077 T2658 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index forceNew:false
[junit4:junit4]   2> 11082 T2658 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@386758db),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11082 T2658 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11083 T2658 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index
[junit4:junit4]   2> 11083 T2658 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 11085 T2658 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 11086 T2658 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 11086 T2658 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 11086 T2658 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 11087 T2658 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 11087 T2658 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 11088 T2658 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 11089 T2658 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 11089 T2658 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 11090 T2658 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 11091 T2658 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 11091 T2658 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 11092 T2658 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 11092 T2658 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 11092 T2658 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 11093 T2658 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 11094 T2658 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11094 T2658 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11095 T2658 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11095 T2658 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11096 T2658 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11097 T2658 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11097 T2658 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11098 T2658 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11098 T2658 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 11099 T2658 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 11105 T2658 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 11108 T2658 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 11109 T2658 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 11111 T2658 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 11112 T2658 oass.SolrIndexSearcher.<init> Opening Searcher@75af6841 main
[junit4:junit4]   2> 11114 T2658 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 11114 T2658 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 11115 T2658 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 11119 T2658 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 11144 T2659 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@75af6841 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 11151 T2658 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 11151 T2658 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11412 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11416 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49858__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49858/_p/ic"}
[junit4:junit4]   2> 11428 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49861__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49861/_p/ic"}
[junit4:junit4]   2> 11429 T2609 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 11430 T2609 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 11442 T2608 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> 11444 T2642 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> 11444 T2657 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> 11445 T2627 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> 11445 T2614 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> 12154 T2658 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 12155 T2658 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49861/_p/ic collection:collection1 shard:shard1
[junit4:junit4]   2> 12166 T2658 oasc.ZkController.register We are http://127.0.0.1:49861/_p/ic/collection1/ and leader is http://127.0.0.1:49855/_p/ic/collection1/
[junit4:junit4]   2> 12166 T2658 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49861/_p/ic
[junit4:junit4]   2> 12167 T2658 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 12168 T2658 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C148 name=collection1 org.apache.solr.core.SolrCore@7248eaae url=http://127.0.0.1:49861/_p/ic/collection1 node=127.0.0.1:49861__p%2Fic C148_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49861__p%2Fic, base_url=http://127.0.0.1:49861/_p/ic}
[junit4:junit4]   2> 12169 T2660 C148 P49861 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 12170 T2658 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12171 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 12173 T2660 C148 P49861 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 12173 T2660 C148 P49861 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12174 T2586 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 12176 T2660 C148 P49861 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12176 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12178 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12358 T2586 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12362 T2586 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49865
[junit4:junit4]   2> 12363 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12363 T2586 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12364 T2586 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562
[junit4:junit4]   2> 12365 T2586 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/solr.xml
[junit4:junit4]   2> 12365 T2586 oasc.CoreContainer.<init> New CoreContainer 462262589
[junit4:junit4]   2> 12366 T2586 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/'
[junit4:junit4]   2> 12366 T2586 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/'
[junit4:junit4]   2> 12401 T2586 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 12402 T2586 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12402 T2586 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12403 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12403 T2586 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12404 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12404 T2586 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12405 T2586 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12405 T2586 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12406 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12417 T2586 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12433 T2586 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49848/solr
[junit4:junit4]   2> 12433 T2586 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12434 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3e896ec4
[junit4:junit4]   2> 12436 T2670 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12437 T2670 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 12436 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12438 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49866
[junit4:junit4]   2> 12438 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49866
[junit4:junit4]   2> 12440 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c46000b with negotiated timeout 20000 for client /127.0.0.1:49866
[junit4:junit4]   2> 12440 T2670 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c46000b, negotiated timeout = 20000
[junit4:junit4]   2> 12440 T2671 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3e896ec4 name:ZooKeeperConnection Watcher:127.0.0.1:49848 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12440 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12442 T2591 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ccf787c46000b
[junit4:junit4]   2> 12443 T2588 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49866 which had sessionid 0x13ccf787c46000b
[junit4:junit4]   2> 12443 T2671 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12443 T2586 oaz.ZooKeeper.close Session: 0x13ccf787c46000b closed
[junit4:junit4]   2> 12444 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 12449 T2586 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49848/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@490346ce
[junit4:junit4]   2> 12450 T2586 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12451 T2672 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49848. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12452 T2672 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49848, initiating session
[junit4:junit4]   2> 12452 T2588 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49867
[junit4:junit4]   2> 12452 T2588 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49867
[junit4:junit4]   2> 12454 T2590 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ccf787c46000c with negotiated timeout 20000 for client /127.0.0.1:49867
[junit4:junit4]   2> 12454 T2672 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49848, sessionid = 0x13ccf787c46000c, negotiated timeout = 20000
[junit4:junit4]   2> 12454 T2673 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@490346ce name:ZooKeeperConnection Watcher:127.0.0.1:49848/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12454 T2586 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12455 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c46000c type:create cxid:0x1 zxid:0x9f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12457 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c46000c type:create cxid:0x2 zxid:0xa0 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12459 T2586 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 12463 T2586 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49865__p%2Fic
[junit4:junit4]   2> 12464 T2591 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ccf787c46000c type:delete cxid:0x9 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49865__p%2Fic Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49865__p%2Fic
[junit4:junit4]   2> 12465 T2586 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49865__p%2Fic
[junit4:junit4]   2> 12468 T2608 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> 12468 T2614 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> 12468 T2642 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> 12468 T2627 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> 12470 T2657 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12470 T2657 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> 12471 T2673 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12474 T2627 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12475 T2642 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12474 T2614 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12474 T2608 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12484 T2674 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/collection1
[junit4:junit4]   2> 12485 T2674 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 12486 T2674 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 12486 T2674 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 12489 T2674 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/collection1/'
[junit4:junit4]   2> 12489 T2674 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 12490 T2674 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/collection1/lib/README' to classloader
[junit4:junit4]   2> 12562 T2674 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 12622 T2674 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 12623 T2674 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 12628 T2674 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 12964 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12965 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49861__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49861/_p/ic"}
[junit4:junit4]   2> 12970 T2614 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> 12972 T2642 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> 12972 T2608 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> 12973 T2673 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> 12973 T2627 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> 12984 T2657 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> 13212 T2674 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 13220 T2674 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 13224 T2674 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 13255 T2674 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 13260 T2674 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 13265 T2674 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 13267 T2674 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 13269 T2674 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360690457562/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/
[junit4:junit4]   2> 13269 T2674 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@551d2790
[junit4:junit4]   2> 13270 T2674 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 13270 T2674 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4 forceNew:false
[junit4:junit4]   2> 13271 T2674 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 13271 T2674 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index/
[junit4:junit4]   2> 13272 T2674 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 13273 T2674 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index forceNew:false
[junit4:junit4]   2> 13277 T2674 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@71bb0b20),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 13277 T2674 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 13278 T2674 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index
[junit4:junit4]   2> 13278 T2674 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 13280 T2674 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 13281 T2674 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 13281 T2674 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 13282 T2674 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 13282 T2674 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 13283 T2674 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 13283 T2674 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 13284 T2674 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 13284 T2674 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 13285 T2674 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 13286 T2674 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 13286 T2674 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 13287 T2674 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 13287 T2674 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 13288 T2674 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 13288 T2674 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 13289 T2674 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13290 T2674 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13290 T2674 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13291 T2674 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13291 T2674 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13292 T2674 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13293 T2674 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13293 T2674 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13294 T2674 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 13295 T2674 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 13301 T2674 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 13305 T2674 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 13307 T2674 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 13310 T2674 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 13313 T2674 oass.SolrIndexSearcher.<init> Opening Searcher@43de5631 main
[junit4:junit4]   2> 13314 T2674 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 13314 T2674 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 13315 T2674 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 13321 T2674 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 13351 T2675 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@43de5631 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 13361 T2674 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 13361 T2674 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 14514 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14515 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49865__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49865/_p/ic"}
[junit4:junit4]   2> 14516 T2609 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 14516 T2609 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 14522 T2608 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> 14522 T2657 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> 14523 T2614 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> 14523 T2642 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> 14523 T2627 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> 14523 T2673 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>  C148_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49861__p%2Fic, base_url=http://127.0.0.1:49861/_p/ic}
[junit4:junit4]   2> 15199 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49855/_p/ic/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 15200 T2660 C148 P49861 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49861/_p/ic START replicas=[http://127.0.0.1:49855/_p/ic/collection1/] nUpdates=100
[junit4:junit4]   2> 15200 T2660 C148 P49861 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 15201 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 15201 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 15201 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 15201 T2660 C148 P49861 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 15202 T2660 C148 P49861 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49855/_p/ic/collection1/. core=collection1
[junit4:junit4]   2> 15202 T2660 C148 P49861 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C149 name=collection1 org.apache.solr.core.SolrCore@4ab199c1 url=http://127.0.0.1:49855/_p/ic/collection1 node=127.0.0.1:49855__p%2Fic C149_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49855__p%2Fic, base_url=http://127.0.0.1:49855/_p/ic, leader=true}
[junit4:junit4]   2> 15212 T2620 C149 P49855 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 15215 T2622 C149 P49855 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 15215 T2622 C149 P49855 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1
[junit4:junit4]   2> 15218 T2622 C149 P49855 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@260f6592),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 15218 T2622 C149 P49855 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 15325 T2622 C149 P49855 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@260f6592),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@260f6592),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 15326 T2622 C149 P49855 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 15327 T2622 C149 P49855 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1
[junit4:junit4]   2> 15327 T2622 C149 P49855 oass.SolrIndexSearcher.<init> Opening Searcher@40df60e2 realtime
[junit4:junit4]   2> 15327 T2622 C149 P49855 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 15328 T2622 C149 P49855 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 114
[junit4:junit4]   2> 15329 T2660 C148 P49861 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 15330 T2660 C148 P49861 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 15333 T2621 C149 P49855 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 15334 T2621 C149 P49855 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 15335 T2660 C148 P49861 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 15336 T2660 C148 P49861 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 15336 T2660 C148 P49861 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 15338 T2619 C149 P49855 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1
[junit4:junit4]   2> 15338 T2619 C149 P49855 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1/index
[junit4:junit4]   2> 15339 T2619 C149 P49855 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> 15340 T2660 C148 P49861 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 15341 T2660 C148 P49861 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708 forceNew:false
[junit4:junit4]   2> 15341 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15341 T2660 C148 P49861 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1e786e) fullCopy=true
[junit4:junit4]   2> 15344 T2623 C149 P49855 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 15346 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index
[junit4:junit4]   2> 15346 T2660 C148 P49861 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 15347 T2660 C148 P49861 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130212204124708
[junit4:junit4]   2> 15348 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15348 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15349 T2660 C148 P49861 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708
[junit4:junit4]   2> 15351 T2660 C148 P49861 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1e786e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 15353 T2660 C148 P49861 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 15354 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15354 T2660 C148 P49861 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 15355 T2660 C148 P49861 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 15355 T2660 C148 P49861 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 15356 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708
[junit4:junit4]   2> 15356 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15359 T2660 C148 P49861 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1e786e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 15359 T2660 C148 P49861 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 15359 T2660 C148 P49861 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 15360 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15360 T2660 C148 P49861 oass.SolrIndexSearcher.<init> Opening Searcher@5b1c192 main
[junit4:junit4]   2> 15362 T2659 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5b1c192 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 15363 T2659 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index
[junit4:junit4]   2> 15363 T2660 C148 P49861 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 15365 T2674 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 15365 T2674 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49865/_p/ic collection:collection1 shard:shard2
[junit4:junit4]   2> 15365 T2660 C148 P49861 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1e786e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1e786e),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 15366 T2660 C148 P49861 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 15367 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 15367 T2660 C148 P49861 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 15368 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index.20130212204124708
[junit4:junit4]   2> 15368 T2660 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3/index
[junit4:junit4]   2> 15368 T2660 C148 P49861 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 15369 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 15369 T2660 C148 P49861 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 15369 T2660 C148 P49861 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15370 T2674 oasc.ZkController.register We are http://127.0.0.1:49865/_p/ic/collection1/ and leader is http://127.0.0.1:49858/_p/ic/collection1/
[junit4:junit4]   2> 15370 T2674 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49865/_p/ic
[junit4:junit4]   2> 15370 T2674 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 15370 T2660 C148 P49861 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 15370 T2674 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C150 name=collection1 org.apache.solr.core.SolrCore@7286f186 url=http://127.0.0.1:49865/_p/ic/collection1 node=127.0.0.1:49865__p%2Fic C150_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49865__p%2Fic, base_url=http://127.0.0.1:49865/_p/ic}
[junit4:junit4]   2> 15372 T2678 C150 P49865 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 15373 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 15373 T2674 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15373 T2678 C150 P49865 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 15374 T2678 C150 P49865 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15375 T2678 C150 P49865 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 15375 T2586 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 15376 T2586 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 15377 T2586 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 15385 T2586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15387 T2586 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 15388 T2586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16033 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16034 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49861__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49861/_p/ic"}
[junit4:junit4]   2> 16041 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49865__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49865/_p/ic"}
[junit4:junit4]   2> 16048 T2673 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> 16048 T2608 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> 16049 T2627 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> 16048 T2657 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> 16049 T2642 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> 16050 T2614 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> 16394 T2586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17401 T2586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C150_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49865__p%2Fic, base_url=http://127.0.0.1:49865/_p/ic}
[junit4:junit4]   2> 18394 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49858/_p/ic/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 18395 T2678 C150 P49865 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49865/_p/ic START replicas=[http://127.0.0.1:49858/_p/ic/collection1/] nUpdates=100
[junit4:junit4]   2> 18396 T2678 C150 P49865 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 18397 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 18397 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 18398 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 18398 T2678 C150 P49865 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 18399 T2678 C150 P49865 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49858/_p/ic/collection1/. core=collection1
[junit4:junit4]   2> 18401 T2678 C150 P49865 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C151 name=collection1 org.apache.solr.core.SolrCore@5561ed6b url=http://127.0.0.1:49858/_p/ic/collection1 node=127.0.0.1:49858__p%2Fic C151_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49858__p%2Fic, base_url=http://127.0.0.1:49858/_p/ic, leader=true}
[junit4:junit4]   2> 18415 T2633 C151 P49858 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 18417 T2635 C151 P49858 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2 
[junit4:junit4]   2> 18417 T2586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18418 T2633 C151 P49858 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2
[junit4:junit4]   2> 18421 T2633 C151 P49858 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b021bb9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 18421 T2633 C151 P49858 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 18423 T2633 C151 P49858 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b021bb9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b021bb9),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 18423 T2633 C151 P49858 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 18424 T2633 C151 P49858 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2
[junit4:junit4]   2> 18425 T2633 C151 P49858 oass.SolrIndexSearcher.<init> Opening Searcher@2fb689fe realtime
[junit4:junit4]   2> 18425 T2633 C151 P49858 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 18425 T2633 C151 P49858 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4]   2> 18427 T2678 C150 P49865 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 18428 T2678 C150 P49865 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 18430 T2636 C151 P49858 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 18430 T2636 C151 P49858 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 18431 T2678 C150 P49865 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 18431 T2678 C150 P49865 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 18431 T2678 C150 P49865 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 18434 T2637 C151 P49858 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2
[junit4:junit4]   2> 18434 T2637 C151 P49858 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2/index
[junit4:junit4]   2> 18435 T2637 C151 P49858 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2 
[junit4:junit4]   2> 18436 T2678 C150 P49865 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 18437 T2678 C150 P49865 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804 forceNew:false
[junit4:junit4]   2> 18437 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18438 T2678 C150 P49865 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2690dd07) fullCopy=true
[junit4:junit4]   2> 18441 T2638 C151 P49858 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 18442 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index
[junit4:junit4]   2> 18443 T2678 C150 P49865 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 18443 T2678 C150 P49865 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130212204127804
[junit4:junit4]   2> 18444 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18445 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18446 T2678 C150 P49865 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804
[junit4:junit4]   2> 18449 T2678 C150 P49865 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2690dd07),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 18450 T2678 C150 P49865 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 18451 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18451 T2678 C150 P49865 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 18451 T2678 C150 P49865 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 18451 T2678 C150 P49865 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 18452 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804
[junit4:junit4]   2> 18453 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18455 T2678 C150 P49865 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2690dd07),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 18455 T2678 C150 P49865 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 18456 T2678 C150 P49865 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 18456 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18457 T2678 C150 P49865 oass.SolrIndexSearcher.<init> Opening Searcher@bc3c7d0 main
[junit4:junit4]   2> 18458 T2675 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bc3c7d0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 18459 T2675 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index
[junit4:junit4]   2> 18459 T2678 C150 P49865 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 18462 T2678 C150 P49865 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2690dd07),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2690dd07),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 18462 T2678 C150 P49865 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 18463 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 18463 T2678 C150 P49865 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 18463 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index.20130212204127804
[junit4:junit4]   2> 18464 T2678 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4/index
[junit4:junit4]   2> 18464 T2678 C150 P49865 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 18464 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 18464 T2678 C150 P49865 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 18465 T2678 C150 P49865 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18466 T2678 C150 P49865 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19077 T2609 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19079 T2609 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49865__p%2Fic",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49865/_p/ic"}
[junit4:junit4]   2> 19096 T2608 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> 19096 T2657 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> 19097 T2642 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> 19097 T2673 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> 19097 T2614 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> 19097 T2627 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> 19421 T2586 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19424 T2586 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C152 name=collection1 org.apache.solr.core.SolrCore@2cb85e3f url=http://127.0.0.1:49851/_p/ic/collection1 node=127.0.0.1:49851__p%2Fic C152_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49851__p%2Fic, base_url=http://127.0.0.1:49851/_p/ic, leader=true}
[junit4:junit4]   2> 19454 T2603 C152 P49851 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data
[junit4:junit4]   2> 19462 T2603 C152 P49851 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@139000ea),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19463 T2603 C152 P49851 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19465 T2603 C152 P49851 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/control/data
[junit4:junit4]   2> 19466 T2603 C152 P49851 oass.SolrIndexSearcher.<init> Opening Searcher@185a5fb5 realtime
[junit4:junit4]   2> 19467 T2603 C152 P49851 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426787364840144896)} 0 14
[junit4:junit4]   2> 19471 T2634 C151 P49858 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty2
[junit4:junit4]   2> 19476 T2619 C149 P49855 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty1
[junit4:junit4]   2>  C150_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49865__p%2Fic, base_url=http://127.0.0.1:49865/_p/ic}
[junit4:junit4]   2> 19483 T2669 C150 P49865 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty4
[junit4:junit4]   2> 19484 T2669 C150 P49865 /update {update.distrib=FROMLEADER&_version_=-1426787364856922112&update.from=http://127.0.0.1:49858/_p/ic/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1426787364856922112)} 0 3
[junit4:junit4]   2>  C148_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49861__p%2Fic, base_url=http://127.0.0.1:49861/_p/ic}
[junit4:junit4]   2> 19486 T2652 C148 P49861 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360690445375/jetty3
[junit4:junit4]   2> 19487 T2652 C148 P49861 /update {update.distrib=FROMLEADER&_version_=-1426787364862164992&update.from=http://127.0.0.1:49855/_p/ic/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1426787364862164992)} 0 2
[junit4:junit4]   2> 19488 T2619 C149 P49855 /update {update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1426787364862164992)} 0 14
[junit4:junit4]   2> 19489 T2634 C151 P49858 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426787364856922112)} 0 20
[junit4:junit4]   2> 19495 T2604 C152 P49851 /update {wt=javabin&version=2} {add=[1 (1426787364881039360)]} 0 3
[junit4:junit4]   2> 19505 T2653 C148 P49861 /update {distrib.from=http://127.0.0.1:49855/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1426787364886282240)]} 0 3
[junit4:junit4]   2> 19506 T2623 C149 P49855 /update {wt=javabin&version=2} {add=[1 (1426787364886282240)]} 0 9
[junit4:junit4]   2> 19511 T2599 C152 P49851 /update {wt=javabin&version=2} {add=[2 (1426787364898865152)]} 0 2
[junit4:junit4]   2> 19524 T2664 C150 P49865 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1426787364905156608)]} 0 3
[junit4:junit4]   2> 19525 T2636 C151 P49858 /update {distrib.from=http://127.0.0.1:49855/_p/ic/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1426787364905156608)]} 0 10
[junit4:junit4]   2> 19526 T2620 C149 P49855 /update {wt=javabin&version=2} {add=[2]} 0 13
[junit4:junit4]   2> 19530 T2600 C152 P49851 /update {wt=javabin&version=2} {add=[3 (1426787364919836672)]} 0 1
[junit4:junit4]   2> 19550 T2665 C150 P49865 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1426787364929273856)]} 0 1
[junit4:junit4]   2> 19551 T2637 C151 P49858 /update {wt=javabin&version=2} {add=[3 (1426787364929273856)]} 0 13
[junit4:junit4]   2> 19555 T2601 C152 P49851 /update {wt=javabin&version=2} {add=[4 (1426787364946051072)]} 0 2
[junit4:junit4]   2> 19568 T2648 C148 P49861 /update {distrib.from=http://127.0.0.1:49855/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1426787364954439680)]} 0 2
[junit4:junit4]   2> 19568 T2622 C149 P49855 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1426787364954439680)]} 0 6
[junit4:junit4]   2> 19585 T2638 C151 P49858 /update {wt=javabin&version=2} {add=[4]} 0 25
[junit4:junit4]   2> 19591 T2602 C152 P49851 /update {wt=javabin&version=2} {add=[5 (1426787364982751232)]} 0 2
[junit4:junit4]   2> 19600 T2666 C150 P49865 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1426787364987994112)]} 0 2
[junit4:junit4]   2> 19601 T2635 C151 P49858 /update {wt=javabin&version=2} {add=[5 (1426787364987994112)]} 0 7
[junit4:junit4]   2> 19606 T2603 C152 P49851 /update {wt=javabin&version=2} {add=[6 (1426787364998479872)]} 0 2
[junit4:junit4]   2> 19623 T2668 C150 P49865 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1426787365004771328)]} 0 2
[junit4:junit4]   2> 19625 T2633 C151 P49858 /update {wt=javabin&version=2} {add=[6 (1426787365004771328)]} 0 15
[junit4:junit4]   2> 19632 T2604 C152 P49851 /update {wt=javabin&version=2} {add=[7 (1426787365024694272)]} 0 3
[junit4:junit4]   2> 19657 T2669 C150 P49865 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1426787365037277184)]} 0 7
[junit4:junit4]   2> 19659 T2634 C151 P49858 /update {wt=javabin&version=2} {add=[7 (1426787365037277184)]} 0 18
[junit4:junit4]   2> 19669 T2599 C152 P49851 /update {wt=javabin&version=2} {add=[8 (1426787365061394432)]} 0 5
[junit4:junit4]   2> 19683 T2649 C148 P49861 /update {distrib.from=http://127.0.0.1:49855/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1426787365072928768)]} 0 2
[junit4:junit4]   2> 19686 T2618 C149 P49855 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1426787365072928768)]} 0 11
[junit4:junit4]   2> 19687 T2637 C151 P49858 /update {wt=javabin&version=2} {add=[8]} 0 14
[junit4:junit4]   2> 19693 T2600 C152 P49851 /update {wt=javabin&version=2} {add=[9 (1426787365088657408)]} 0 3
[junit4:junit4]   2> 19704 T2664 C150 P49865 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1426787365095997440)]} 0 2
[junit4:junit4]   2> 19705 T2638 C151 P49858 /update {wt=javabin&version=2} {add=[9 (1426787365095997440)]} 0 9
[junit4:junit4]   2> 19722 T2601 C152 P49851 /update {wt=javabin&version=2} {add=[10 (1426787365107531776)]} 0 14
[junit4:junit4]   2> 19735 T2650 C148 P49861 /update {distrib.from=http://127.0.0.1:49855/_p/ic/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1426787365128503296)]} 0 2
[junit4:junit4]   2> 19736 T2621 C149 P49855 /update {distrib.from=http://127.0.0.1:49858/_p/ic/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (14267

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

tp.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:647)
[junit4:junit4]    > 	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
[junit4:junit4]    > 	... 5 more
[junit4:junit4]    > Throwable #2: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=2922, name=testExecutor-1435-thread-12, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4]    > Caused by: java.lang.RuntimeException: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:49861/_p/ic
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([71DF31F42561CAC2]:0)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZkTest$2.run(BasicDistributedZkTest.java:722)
[junit4:junit4]    > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
[junit4:junit4]    > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]    > Caused by: org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:49861/_p/ic
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:416)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZkTest$2.run(BasicDistributedZkTest.java:720)
[junit4:junit4]    > 	... 3 more
[junit4:junit4]    > Caused by: java.net.SocketException: Invalid argument
[junit4:junit4]    > 	at java.net.SocketInputStream.socketRead0(Native Method)
[junit4:junit4]    > 	at java.net.SocketInputStream.read(SocketInputStream.java:150)
[junit4:junit4]    > 	at java.net.SocketInputStream.read(SocketInputStream.java:121)
[junit4:junit4]    > 	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:149)
[junit4:junit4]    > 	at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:111)
[junit4:junit4]    > 	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:264)
[junit4:junit4]    > 	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:98)
[junit4:junit4]    > 	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:252)
[junit4:junit4]    > 	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:282)
[junit4:junit4]    > 	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:247)
[junit4:junit4]    > 	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:216)
[junit4:junit4]    > 	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:298)
[junit4:junit4]    > 	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
[junit4:junit4]    > 	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:647)
[junit4:junit4]    > 	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
[junit4:junit4]    > 	... 5 more
[junit4:junit4]   2> 202169 T2586 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 202551 T2657 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 202552 T2657 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> 202552 T2657 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 202553 T2657 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 202582 T2585 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4]   2> 202828 T2673 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 202828 T2673 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 202828 T2673 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=HighCompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=494), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=494)), sim=DefaultSimilarity, locale=sl, timezone=Asia/Riyadh87
[junit4:junit4]   2> NOTE: Mac OS X 10.8.2 x86_64/Oracle Corporation 1.7.0_10 (64-bit)/cpus=2,threads=8,free=73568240,total=220127232
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestCodecSupport, BasicDistributedZk2Test, TestBinaryResponseWriter, TestOmitPositions, ZkCLITest, TestIBSimilarityFactory, TestLMJelinekMercerSimilarityFactory, AutoCommitTest, TestStressReorder, TestRemoteStreaming, QueryElevationComponentTest, SignatureUpdateProcessorFactoryTest, TestStressRecovery, CurrencyFieldTest, CopyFieldTest, TestNumberUtils, ShowFileRequestHandlerTest, FullSolrCloudDistribCmdsTest, TestGroupingSearch, DocumentAnalysisRequestHandlerTest, RAMDirectoryFactoryTest, ConvertedLegacyTest, PingRequestHandlerTest, FileBasedSpellCheckerTest, TestPropInject, OverseerTest, DistanceFunctionTest, SpellingQueryConverterTest, SoftAutoCommitTest, BadComponentTest, ShardRoutingTest, TestFaceting, ScriptEngineTest, PreAnalyzedFieldTest, TimeZoneUtilsTest, TestMergePolicyConfig, LegacyHTMLStripCharFilterTest, DebugComponentTest, CacheHeaderTest, OutputWriterTest, TestValueSourceCache, DocumentBuilderTest, ClusterStateUpdateTest, SolrIndexConfigTest, SuggesterTSTTest, TermVectorComponentDistributedTest, TestUpdate, CircularListTest, PathHierarchyTokenizerFactoryTest, SpellPossibilityIteratorTest, TestHashPartitioner, LeaderElectionTest, TestLFUCache, DOMUtilTest, TestLazyCores, LoggingHandlerTest, SuggesterWFSTTest, DirectUpdateHandlerOptimizeTest, FieldAnalysisRequestHandlerTest, SolrInfoMBeanTest, TestPseudoReturnFields, TestExtendedDismaxParser, TestStressLucene, TestSolrDeletionPolicy2, TestSolrQueryParser, SystemInfoHandlerTest, SuggesterTest, UpdateParamsTest, ReturnFieldsTest, TestSystemIdResolver, DirectSolrConnectionTest, QueryEqualityTest, TestReplicationHandler, ExternalFileFieldSortTest, TestSolrIndexConfig, SearchHandlerTest, TestMultiCoreConfBootstrap, TestRandomFaceting, TestXIncludeConfig, TestJoin, TestRangeQuery, AnalysisAfterCoreReloadTest, PluginInfoTest, RegexBoostProcessorTest, TestCSVLoader, TestSolrJ, TestBinaryField, TestPartialUpdateDeduplication, DistributedQueryElevationComponentTest, TestLMDirichletSimilarityFactory, OverseerCollectionProcessorTest, DistributedSpellCheckComponentTest, TestElisionMultitermQuery, SolrCoreCheckLockOnStartupTest, PrimUtilsTest, MinimalSchemaTest, LukeRequestHandlerTest, SuggesterFSTTest, SpatialFilterTest, StandardRequestHandlerTest, TestTrie, StatelessScriptUpdateProcessorFactoryTest, TestFunctionQuery, SOLR749Test, DateMathParserTest, WordBreakSolrSpellCheckerTest, ResponseLogComponentTest, SimpleFacetsTest, TermVectorComponentTest, SolrPluginUtilsTest, NotRequiredUniqueKeyTest, RecoveryZkTest, JSONWriterTest, CSVRequestHandlerTest, TestWriterPerf, SynonymTokenizerTest, TestPerFieldSimilarity, DirectUpdateHandlerTest, TestSuggestSpellingConverter, BasicDistributedZkTest]
[junit4:junit4] Completed in 202.88s, 1 test, 1 error <<< FAILURES!

[...truncated 388 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:381: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:361: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:183: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:447: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1202: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:865: There were test failures: 250 suites, 1040 tests, 1 error, 13 ignored (2 assumptions)

Total time: 63 minutes 52 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.7.0 -XX:+UseSerialGC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message