lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3555 - Failure
Date Sat, 15 Dec 2012 04:59:01 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3555/

1 tests failed.
FAILED:  org.apache.solr.cloud.SyncSliceTest.testDistribSearch

Error Message:
Shard still reported as live in zk - 0 jetty

Stack Trace:
java.lang.AssertionError: Shard still reported as live in zk - 0 jetty
	at __randomizedtesting.SeedInfo.seed([8F345A6AA4FFB92D:ED2D472D3A0D911]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.waitToSeeNotLive(AbstractFullDistribZkTestBase.java:1239)
	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.waitToSeeNotLive(AbstractFullDistribZkTestBase.java:1224)
	at org.apache.solr.cloud.SyncSliceTest.waitToSeeDownInClusterState(SyncSliceTest.java:259)
	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:163)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:793)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)




Build Log:
[...truncated 8923 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4]   2> 0 T338 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 4 T338 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1355546904722
[junit4:junit4]   2> 5 T338 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 6 T339 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 8 T339 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 8 T339 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 8 T339 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 9 T339 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 10 T339 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 107 T338 oasc.ZkTestServer.run start zk server on port:30527
[junit4:junit4]   2> 107 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@59d9f3db
[junit4:junit4]   2> 108 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 109 T344 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 109 T344 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 110 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30528
[junit4:junit4]   2> 110 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30528
[junit4:junit4]   2> 110 T342 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 113 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970000 with negotiated timeout 10000 for client /140.211.11.196:30528
[junit4:junit4]   2> 113 T344 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970000, negotiated timeout = 10000
[junit4:junit4]   2> 114 T345 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59d9f3db name:ZooKeeperConnection Watcher:127.0.0.1:30527 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 114 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 114 T338 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 133 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce448970000
[junit4:junit4]   2> 139 T345 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 139 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:30528 which had sessionid 0x13b9ce448970000
[junit4:junit4]   2> 139 T338 oaz.ZooKeeper.close Session: 0x13b9ce448970000 closed
[junit4:junit4]   2> 140 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4a191c9
[junit4:junit4]   2> 141 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 141 T346 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 141 T346 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 142 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30529
[junit4:junit4]   2> 142 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30529
[junit4:junit4]   2> 143 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970001 with negotiated timeout 10000 for client /140.211.11.196:30529
[junit4:junit4]   2> 143 T346 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970001, negotiated timeout = 10000
[junit4:junit4]   2> 144 T347 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a191c9 name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 144 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 145 T338 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 155 T338 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 157 T338 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 160 T338 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 163 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 164 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 179 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 180 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 284 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 285 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 288 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 289 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 297 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 298 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 301 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 301 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 304 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 305 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 308 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 309 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 312 T338 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 312 T338 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 319 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce448970001
[junit4:junit4]   2> 320 T347 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 320 T338 oaz.ZooKeeper.close Session: 0x13b9ce448970001 closed
[junit4:junit4]   2> 320 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:30529 which had sessionid 0x13b9ce448970001
[junit4:junit4]   2> 451 T338 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 454 T338 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:30532
[junit4:junit4]   2> 455 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 456 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038
[junit4:junit4]   2> 456 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for deduced Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/'
[junit4:junit4]   2> 487 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 487 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 488 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038
[junit4:junit4]   2> 488 T338 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/solr.xml
[junit4:junit4]   2> 488 T338 oasc.CoreContainer.<init> New CoreContainer 1908473483
[junit4:junit4]   2> 489 T338 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/'
[junit4:junit4]   2> 489 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/'
[junit4:junit4]   2> 515 T338 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 529 T338 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:30527/solr
[junit4:junit4]   2> 529 T338 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 530 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@75c6db01
[junit4:junit4]   2> 531 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 531 T357 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 532 T357 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 532 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30533
[junit4:junit4]   2> 532 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30533
[junit4:junit4]   2> 534 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970002 with negotiated timeout 20000 for client /140.211.11.196:30533
[junit4:junit4]   2> 534 T357 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970002, negotiated timeout = 20000
[junit4:junit4]   2> 534 T358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@75c6db01 name:ZooKeeperConnection Watcher:127.0.0.1:30527 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 535 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 536 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce448970002
[junit4:junit4]   2> 537 T358 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 537 T338 oaz.ZooKeeper.close Session: 0x13b9ce448970002 closed
[junit4:junit4]   2> 537 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:30533 which had sessionid 0x13b9ce448970002
[junit4:junit4]   2> 538 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=8000 watcher=org.apache.solr.common.cloud.ConnectionManager@3f612775
[junit4:junit4]   2> 538 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 539 T359 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 539 T359 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 539 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30534
[junit4:junit4]   2> 540 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30534
[junit4:junit4]   2> 545 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970003 with negotiated timeout 8000 for client /140.211.11.196:30534
[junit4:junit4]   2> 545 T359 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970003, negotiated timeout = 8000
[junit4:junit4]   2> 546 T360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f612775 name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 546 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 548 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 554 T338 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 556 T338 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:30532_
[junit4:junit4]   2> 557 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:delete cxid:0x7 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:30532_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:30532_
[junit4:junit4]   2> 558 T338 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:30532_
[junit4:junit4]   2> 567 T338 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 568 T338 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 568 T338 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 569 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 569 T338 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 570 T338 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 570 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 571 T338 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 571 T338 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 572 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 590 T338 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 604 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:delete cxid:0x15 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 605 T338 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 608 T338 oasc.Overseer.start Overseer (id=88837121948188675-127.0.0.1:30532_-n_0000000000) starting
[junit4:junit4]   2> 609 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x1a zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 615 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x1b zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 617 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x1c zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 623 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x1d zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 625 T362 oasc.OverseerCollectionProcessor.run Process current queue of collection messages
[junit4:junit4]   2> 625 T338 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 629 T338 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 632 T361 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 638 T363 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/collection1
[junit4:junit4]   2> 639 T363 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 640 T363 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 640 T363 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 642 T363 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/collection1/'
[junit4:junit4]   2> 643 T363 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 644 T363 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/collection1/lib/README' to classloader
[junit4:junit4]   2> 702 T363 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 804 T363 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 905 T363 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 914 T363 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1551 T363 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1569 T363 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1572 T363 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1585 T363 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1589 T363 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1593 T363 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1594 T363 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1595 T363 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1355546905038/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data/
[junit4:junit4]   2> 1595 T363 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2716630b
[junit4:junit4]   2> 1596 T363 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 1619 T363 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data forceNew:false
[junit4:junit4]   2> 1619 T363 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data
[junit4:junit4]   2> 1620 T363 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data/index/
[junit4:junit4]   2> 1620 T363 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1621 T363 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data/index forceNew:false
[junit4:junit4]   2> 1625 T363 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@33bb9f34),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1626 T363 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1626 T363 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data/index
[junit4:junit4]   2> 1626 T363 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 1628 T363 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1628 T363 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 1628 T363 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1629 T363 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 1629 T363 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1630 T363 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1630 T363 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1631 T363 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1632 T363 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1633 T363 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 1633 T363 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 1634 T363 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1635 T363 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 1635 T363 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 1635 T363 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 1636 T363 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1637 T363 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1638 T363 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1639 T363 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1639 T363 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1640 T363 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1641 T363 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1642 T363 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1643 T363 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1644 T363 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 1645 T363 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 1653 T363 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1656 T363 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 1657 T363 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> 1659 T363 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/control/data
[junit4:junit4]   2> 1661 T363 oass.SolrIndexSearcher.<init> Opening Searcher@1eaa3adf main
[junit4:junit4]   2> 1678 T363 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1678 T363 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1679 T363 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 1696 T363 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 1751 T364 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1eaa3adf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1755 T363 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1755 T363 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1756 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x56 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 2140 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2141 T361 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:30532_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:30532"}
[junit4:junit4]   2> 2141 T361 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2150 T361 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2150 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x5e zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 2170 T360 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> 2267 T363 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2267 T363 oasc.ZkController.register Register shard - core:collection1 address:http://127.0.0.1:30532 shardId:shard1
[junit4:junit4]   2> 2268 T363 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2282 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:delete cxid:0x78 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> 2283 T363 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2283 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x79 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2285 T363 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2285 T363 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2286 T363 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:30532/collection1/
[junit4:junit4]   2> 2286 T363 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2286 T363 oasc.SyncStrategy.syncToMe http://127.0.0.1:30532/collection1/ has no replicas
[junit4:junit4]   2> 2287 T363 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:30532/collection1/
[junit4:junit4]   2> 2287 T363 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2290 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970003 type:create cxid:0x83 zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2675 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2691 T360 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 2751 T363 oasc.ZkController.register We are http://127.0.0.1:30532/collection1/ and leader is http://127.0.0.1:30532/collection1/
[junit4:junit4]   2> 2755 T363 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:30532
[junit4:junit4]   2> 2756 T363 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 2756 T363 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 2756 T363 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 2759 T363 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2760 T338 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 2761 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 2761 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 2780 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 2798 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6c5d2aea
[junit4:junit4]   2> 2799 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 2799 T365 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 2800 T365 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 2800 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30535
[junit4:junit4]   2> 2801 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30535
[junit4:junit4]   2> 2802 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970004 with negotiated timeout 10000 for client /140.211.11.196:30535
[junit4:junit4]   2> 2802 T365 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970004, negotiated timeout = 10000
[junit4:junit4]   2> 2803 T366 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c5d2aea name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 2803 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 2804 T338 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 2808 T338 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 2973 T338 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 2976 T338 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:30536
[junit4:junit4]   2> 2977 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 2978 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526
[junit4:junit4]   2> 2978 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for deduced Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/'
[junit4:junit4]   2> 3022 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3023 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3023 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526
[junit4:junit4]   2> 3024 T338 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/solr.xml
[junit4:junit4]   2> 3024 T338 oasc.CoreContainer.<init> New CoreContainer 1081875037
[junit4:junit4]   2> 3025 T338 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/'
[junit4:junit4]   2> 3025 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/'
[junit4:junit4]   2> 3059 T338 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3077 T338 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:30527/solr
[junit4:junit4]   2> 3077 T338 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3078 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@21b6a333
[junit4:junit4]   2> 3079 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3080 T376 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3080 T376 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 3081 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30537
[junit4:junit4]   2> 3081 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30537
[junit4:junit4]   2> 3083 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970005 with negotiated timeout 20000 for client /140.211.11.196:30537
[junit4:junit4]   2> 3083 T376 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970005, negotiated timeout = 20000
[junit4:junit4]   2> 3084 T377 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21b6a333 name:ZooKeeperConnection Watcher:127.0.0.1:30527 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3084 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3086 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce448970005
[junit4:junit4]   2> 3094 T377 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3094 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:30537 which had sessionid 0x13b9ce448970005
[junit4:junit4]   2> 3094 T338 oaz.ZooKeeper.close Session: 0x13b9ce448970005 closed
[junit4:junit4]   2> 3094 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=8000 watcher=org.apache.solr.common.cloud.ConnectionManager@27871523
[junit4:junit4]   2> 3096 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3096 T378 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3097 T378 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 3097 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:30538
[junit4:junit4]   2> 3097 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:30538
[junit4:junit4]   2> 3099 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970006 with negotiated timeout 8000 for client /140.211.11.196:30538
[junit4:junit4]   2> 3099 T378 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970006, negotiated timeout = 8000
[junit4:junit4]   2> 3099 T379 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@27871523 name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3099 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3101 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3102 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3110 T338 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:30536_
[junit4:junit4]   2> 3111 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970006 type:delete cxid:0x4 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:30536_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:30536_
[junit4:junit4]   2> 3112 T338 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:30536_
[junit4:junit4]   2> 3115 T366 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 3115 T360 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 3116 T360 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> 3116 T338 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 3117 T338 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3118 T338 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 3118 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3119 T338 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3120 T338 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3120 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3121 T338 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3121 T338 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3122 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 3143 T338 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3152 T380 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/collection1
[junit4:junit4]   2> 3152 T380 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 3153 T380 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 3153 T380 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 3155 T380 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/collection1/'
[junit4:junit4]   2> 3156 T380 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/collection1/lib/README' to classloader
[junit4:junit4]   2> 3157 T380 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 3206 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3207 T361 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:30532_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:30532"}
[junit4:junit4]   2> 3212 T380 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 3220 T379 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> 3220 T366 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> 3220 T360 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> 3284 T380 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 3386 T380 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 3406 T380 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4036 T380 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4048 T380 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4052 T380 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 4071 T380 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4076 T380 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4081 T380 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4083 T380 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4085 T380 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1355546907526/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/
[junit4:junit4]   2> 4086 T380 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2716630b
[junit4:junit4]   2> 4086 T380 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 4087 T380 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1 forceNew:false
[junit4:junit4]   2> 4088 T380 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 4088 T380 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index/
[junit4:junit4]   2> 4089 T380 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 4090 T380 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index forceNew:false
[junit4:junit4]   2> 4096 T380 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 4096 T380 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 4097 T380 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index
[junit4:junit4]   2> 4097 T380 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 4100 T380 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 4100 T380 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 4101 T380 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 4101 T380 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 4102 T380 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 4102 T380 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 4103 T380 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 4104 T380 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 4106 T380 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 4107 T380 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 4109 T380 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 4109 T380 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 4111 T380 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 4111 T380 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 4111 T380 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 4113 T380 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 4114 T380 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4115 T380 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4117 T380 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4118 T380 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4120 T380 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4121 T380 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4122 T380 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4124 T380 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 4125 T380 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 4127 T380 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 4140 T380 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 4144 T380 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 4147 T380 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> 4149 T380 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 4151 T380 oass.SolrIndexSearcher.<init> Opening Searcher@24e8ad9a main
[junit4:junit4]   2> 4152 T380 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 4153 T380 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 4153 T380 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 4161 T380 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 4220 T381 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@24e8ad9a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 4227 T380 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 4227 T380 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 4730 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4731 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:30536_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:30536"}
[junit4:junit4]   2> 4731 T361 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4]   2> 4731 T361 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 4744 T379 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> 4744 T360 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> 4744 T366 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> 5231 T380 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 5231 T380 oasc.ZkController.register Register shard - core:collection1 address:http://127.0.0.1:30536 shardId:shard1
[junit4:junit4]   2> 5232 T380 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 5252 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970006 type:delete cxid:0x45 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 5253 T380 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 5254 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970006 type:create cxid:0x46 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 5268 T380 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 5269 T380 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 5269 T380 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:30536/collection1/
[junit4:junit4]   2> 5270 T380 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 5270 T380 oasc.SyncStrategy.syncToMe http://127.0.0.1:30536/collection1/ has no replicas
[junit4:junit4]   2> 5270 T380 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:30536/collection1/
[junit4:junit4]   2> 5271 T380 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 5278 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970006 type:create cxid:0x50 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 5754 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5773 T360 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> 5773 T366 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> 5773 T379 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> 5797 T380 oasc.ZkController.register We are http://127.0.0.1:30536/collection1/ and leader is http://127.0.0.1:30536/collection1/
[junit4:junit4]   2> 5797 T380 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:30536
[junit4:junit4]   2> 5798 T380 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 5798 T380 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 5798 T380 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 5847 T380 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5849 T338 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 5850 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 5850 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 6034 T338 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 6037 T338 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:51238
[junit4:junit4]   2> 6038 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 6039 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584
[junit4:junit4]   2> 6039 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for deduced Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/'
[junit4:junit4]   2> 6081 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 6082 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 6083 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584
[junit4:junit4]   2> 6083 T338 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/solr.xml
[junit4:junit4]   2> 6084 T338 oasc.CoreContainer.<init> New CoreContainer 186177888
[junit4:junit4]   2> 6084 T338 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/'
[junit4:junit4]   2> 6085 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/'
[junit4:junit4]   2> 6120 T338 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 6138 T338 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:30527/solr
[junit4:junit4]   2> 6139 T338 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 6139 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2258b5ff
[junit4:junit4]   2> 6140 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 6141 T391 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 6142 T391 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 6142 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:52774
[junit4:junit4]   2> 6143 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:52774
[junit4:junit4]   2> 6145 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970007 with negotiated timeout 20000 for client /140.211.11.196:52774
[junit4:junit4]   2> 6145 T391 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970007, negotiated timeout = 20000
[junit4:junit4]   2> 6145 T392 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2258b5ff name:ZooKeeperConnection Watcher:127.0.0.1:30527 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 6146 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 6147 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce448970007
[junit4:junit4]   2> 6174 T392 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 6174 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:52774 which had sessionid 0x13b9ce448970007
[junit4:junit4]   2> 6174 T338 oaz.ZooKeeper.close Session: 0x13b9ce448970007 closed
[junit4:junit4]   2> 6176 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=8000 watcher=org.apache.solr.common.cloud.ConnectionManager@4fbd7fe9
[junit4:junit4]   2> 6177 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 6177 T393 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 6178 T393 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 6178 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:54535
[junit4:junit4]   2> 6179 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:54535
[junit4:junit4]   2> 6212 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970008 with negotiated timeout 8000 for client /140.211.11.196:54535
[junit4:junit4]   2> 6212 T393 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970008, negotiated timeout = 8000
[junit4:junit4]   2> 6213 T394 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4fbd7fe9 name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 6213 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 6214 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6240 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6242 T338 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51238_
[junit4:junit4]   2> 6243 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce448970008 type:delete cxid:0x4 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:51238_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:51238_
[junit4:junit4]   2> 6256 T338 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51238_
[junit4:junit4]   2> 6284 T379 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> 6285 T366 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 6285 T360 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 6285 T366 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> 6285 T338 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 6285 T360 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> 6286 T338 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 6287 T338 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 6288 T379 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 6288 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 6288 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6288 T338 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 6289 T338 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 6289 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:30536_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:30536"}
[junit4:junit4]   2> 6290 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 6290 T338 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 6291 T338 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 6291 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 6331 T379 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> 6331 T366 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> 6333 T338 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 6369 T360 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> 6372 T395 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/collection1
[junit4:junit4]   2> 6373 T395 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 6374 T395 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 6374 T395 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 6376 T395 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/collection1/'
[junit4:junit4]   2> 6378 T395 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/collection1/lib/README' to classloader
[junit4:junit4]   2> 6378 T395 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 6445 T395 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 6523 T395 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 6625 T395 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 6634 T395 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 7324 T395 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 7337 T395 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 7341 T395 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 7363 T395 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 7369 T395 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 7374 T395 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 7376 T395 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 7378 T395 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1355546910584/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/
[junit4:junit4]   2> 7378 T395 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2716630b
[junit4:junit4]   2> 7379 T395 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 7380 T395 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2 forceNew:false
[junit4:junit4]   2> 7380 T395 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 7381 T395 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index/
[junit4:junit4]   2> 7382 T395 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 7383 T395 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index forceNew:false
[junit4:junit4]   2> 7441 T395 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@228bf9b8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 7442 T395 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 7442 T395 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index
[junit4:junit4]   2> 7443 T395 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 7445 T395 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 7446 T395 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 7446 T395 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 7447 T395 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 7447 T395 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 7448 T395 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 7448 T395 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 7450 T395 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 7451 T395 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 7453 T395 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 7454 T395 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 7455 T395 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 7456 T395 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 7456 T395 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 7457 T395 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 7458 T395 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 7459 T395 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7461 T395 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7462 T395 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7463 T395 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7465 T395 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7466 T395 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7468 T395 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7469 T395 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 7470 T395 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 7472 T395 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 7486 T395 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 7492 T395 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 7494 T395 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> 7497 T395 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 7499 T395 oass.SolrIndexSearcher.<init> Opening Searcher@f1c6dba main
[junit4:junit4]   2> 7500 T395 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 7501 T395 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 7501 T395 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 7519 T395 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 7585 T396 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f1c6dba main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 7592 T395 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 7592 T395 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7872 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7873 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:51238_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:51238"}
[junit4:junit4]   2> 7873 T361 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 7874 T361 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 7887 T379 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> 7887 T394 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> 7887 T366 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> 7887 T360 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> 8095 T395 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 8095 T395 oasc.ZkController.register Register shard - core:collection1 address:http://127.0.0.1:51238 shardId:shard1
[junit4:junit4]   2> 8101 T395 oasc.ZkController.register We are http://127.0.0.1:51238/collection1/ and leader is http://127.0.0.1:30536/collection1/
[junit4:junit4]   2> 8102 T395 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51238
[junit4:junit4]   2> 8102 T395 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 8102 T395 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C17 name=collection1 org.apache.solr.core.SolrCore@5495ab88 url=http://127.0.0.1:51238/collection1 node=127.0.0.1:51238_
[junit4:junit4]   2> 8110 T397 C17 P51238 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 8111 T395 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8111 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 8112 T397 C17 P51238 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 8112 T397 C17 P51238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8113 T338 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 8113 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8114 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8114 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:30536/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 8126 T397 C17 P51238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4]   2> 8149 T397 C17 P51238 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51238 START replicas=[http://127.0.0.1:30536/collection1/] nUpdates=100
[junit4:junit4]   2> 8150 T397 C17 P51238 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 8151 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 8151 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 8151 T397 C17 P51238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C18 name=collection1 org.apache.solr.core.SolrCore@2823a2b4 url=http://127.0.0.1:30536/collection1 node=127.0.0.1:30536_
[junit4:junit4]   2> 8164 T369 C18 P30536 REQ /get {distrib=false&qt=/get&wt=javabin&version=2&getVersions=100} status=0 QTime=1 
[junit4:junit4]   2> 8307 T338 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8310 T338 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16867
[junit4:junit4]   2> 8311 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8311 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847
[junit4:junit4]   2> 8312 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for deduced Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/'
[junit4:junit4]   2> 8353 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8354 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8355 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847
[junit4:junit4]   2> 8355 T338 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/solr.xml
[junit4:junit4]   2> 8356 T338 oasc.CoreContainer.<init> New CoreContainer 2092801873
[junit4:junit4]   2> 8356 T338 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/'
[junit4:junit4]   2> 8357 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/'
[junit4:junit4]   2> 8398 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8401 T361 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":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:51238_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:51238"}
[junit4:junit4]   2> 8408 T338 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8420 T379 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> 8420 T366 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> 8420 T360 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> 8421 T394 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> 8428 T338 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:30527/solr
[junit4:junit4]   2> 8429 T338 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8430 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1d6bd59b
[junit4:junit4]   2> 8431 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8431 T408 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8432 T408 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 8432 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:14995
[junit4:junit4]   2> 8433 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:14995
[junit4:junit4]   2> 8434 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce448970009 with negotiated timeout 20000 for client /140.211.11.196:14995
[junit4:junit4]   2> 8434 T408 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce448970009, negotiated timeout = 20000
[junit4:junit4]   2> 8435 T409 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d6bd59b name:ZooKeeperConnection Watcher:127.0.0.1:30527 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8435 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8437 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce448970009
[junit4:junit4]   2> 8438 T409 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8439 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:14995 which had sessionid 0x13b9ce448970009
[junit4:junit4]   2> 8438 T338 oaz.ZooKeeper.close Session: 0x13b9ce448970009 closed
[junit4:junit4]   2> 8440 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=8000 watcher=org.apache.solr.common.cloud.ConnectionManager@1812835
[junit4:junit4]   2> 8441 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8442 T410 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8443 T410 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 8443 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:17794
[junit4:junit4]   2> 8443 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:17794
[junit4:junit4]   2> 8445 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce44897000a with negotiated timeout 8000 for client /140.211.11.196:17794
[junit4:junit4]   2> 8445 T410 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce44897000a, negotiated timeout = 8000
[junit4:junit4]   2> 8445 T411 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1812835 name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8446 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8448 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce44897000a type:create cxid:0x1 zxid:0x84 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8450 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce44897000a type:create cxid:0x2 zxid:0x85 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8452 T338 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16867_
[junit4:junit4]   2> 8453 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce44897000a type:delete cxid:0x4 zxid:0x86 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:16867_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:16867_
[junit4:junit4]   2> 8459 T338 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16867_
[junit4:junit4]   2> 8463 T379 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> 8463 T360 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 8463 T366 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 8464 T360 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> 8464 T394 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 8464 T366 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> 8465 T394 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> 8464 T338 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 8465 T379 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 8466 T338 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8467 T338 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 8467 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8468 T338 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8468 T338 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8469 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8469 T338 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8470 T338 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8471 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 8494 T338 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 8504 T412 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/collection1
[junit4:junit4]   2> 8505 T412 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 8506 T412 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 8506 T412 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 8508 T412 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/collection1/'
[junit4:junit4]   2> 8509 T412 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 8510 T412 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/collection1/lib/README' to classloader
[junit4:junit4]   2> 8563 T412 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 8636 T412 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 8737 T412 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 8749 T412 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9488 T412 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9501 T412 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9505 T412 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9531 T412 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9539 T412 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9547 T412 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9549 T412 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9551 T412 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1355546912847/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/
[junit4:junit4]   2> 9552 T412 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2716630b
[junit4:junit4]   2> 9553 T412 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 9554 T412 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3 forceNew:false
[junit4:junit4]   2> 9555 T412 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 9556 T412 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index/
[junit4:junit4]   2> 9557 T412 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9558 T412 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index forceNew:false
[junit4:junit4]   2> 9566 T412 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4088f3be),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9567 T412 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9568 T412 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index
[junit4:junit4]   2> 9569 T412 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 9572 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9573 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 9574 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9574 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 9575 T412 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9576 T412 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9577 T412 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9579 T412 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9581 T412 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9583 T412 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 9584 T412 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 9585 T412 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9587 T412 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 9587 T412 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 9588 T412 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 9590 T412 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9592 T412 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9594 T412 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9596 T412 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9598 T412 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9600 T412 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9602 T412 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9604 T412 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9606 T412 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9608 T412 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 9610 T412 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 9630 T412 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9638 T412 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 9641 T412 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> 9645 T412 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 9648 T412 oass.SolrIndexSearcher.<init> Opening Searcher@2204a3fa main
[junit4:junit4]   2> 9650 T412 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9651 T412 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9652 T412 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 9663 T412 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 9732 T413 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2204a3fa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9742 T412 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9743 T412 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9934 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9935 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:16867_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16867"}
[junit4:junit4]   2> 9935 T361 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 9935 T361 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 9945 T411 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> 9945 T394 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> 9945 T379 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> 9945 T366 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> 9945 T360 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> 10246 T412 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 10246 T412 oasc.ZkController.register Register shard - core:collection1 address:http://127.0.0.1:16867 shardId:shard1
[junit4:junit4]   2> 10251 T412 oasc.ZkController.register We are http://127.0.0.1:16867/collection1/ and leader is http://127.0.0.1:30536/collection1/
[junit4:junit4]   2> 10252 T412 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16867
[junit4:junit4]   2> 10252 T412 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 10252 T412 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C19 name=collection1 org.apache.solr.core.SolrCore@74d9b172 url=http://127.0.0.1:16867/collection1 node=127.0.0.1:16867_
[junit4:junit4]   2> 10253 T414 C19 P16867 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 10254 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 10254 T412 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10254 T414 C19 P16867 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 10254 T414 C19 P16867 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10255 T338 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 10256 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:30536/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 10256 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 10257 T414 C19 P16867 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:16867 START replicas=[http://127.0.0.1:30536/collection1/] nUpdates=100
[junit4:junit4]   2> 10257 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 10258 T414 C19 P16867 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 10258 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 10259 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 10259 T414 C19 P16867 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 10262 T369 C18 P30536 REQ /get {distrib=false&qt=/get&wt=javabin&version=2&getVersions=100} status=0 QTime=0 
[junit4:junit4]   2> 10457 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10458 T361 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":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:16867_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16867"}
[junit4:junit4]   2> 10473 T394 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> 10473 T379 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> 10473 T360 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> 10473 T366 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> 10473 T411 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> 10540 T338 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 10543 T338 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15936
[junit4:junit4]   2> 10545 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 10546 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996
[junit4:junit4]   2> 10547 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for deduced Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/'
[junit4:junit4]   2> 10601 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 10602 T338 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 10602 T338 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996
[junit4:junit4]   2> 10603 T338 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/solr.xml
[junit4:junit4]   2> 10603 T338 oasc.CoreContainer.<init> New CoreContainer 793352002
[junit4:junit4]   2> 10604 T338 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/'
[junit4:junit4]   2> 10605 T338 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/'
[junit4:junit4]   2> 10656 T338 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 10677 T338 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:30527/solr
[junit4:junit4]   2> 10678 T338 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 10678 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3020a258
[junit4:junit4]   2> 10680 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 10680 T425 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 10681 T425 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 10681 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:13037
[junit4:junit4]   2> 10682 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:13037
[junit4:junit4]   2> 10684 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce44897000b with negotiated timeout 20000 for client /140.211.11.196:13037
[junit4:junit4]   2> 10684 T425 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce44897000b, negotiated timeout = 20000
[junit4:junit4]   2> 10684 T426 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3020a258 name:ZooKeeperConnection Watcher:127.0.0.1:30527 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 10685 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 10687 T343 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13b9ce44897000b
[junit4:junit4]   2> 10688 T426 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 10688 T340 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:13037 which had sessionid 0x13b9ce44897000b
[junit4:junit4]   2> 10688 T338 oaz.ZooKeeper.close Session: 0x13b9ce44897000b closed
[junit4:junit4]   2> 10689 T338 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:30527/solr sessionTimeout=8000 watcher=org.apache.solr.common.cloud.ConnectionManager@2f38fd40
[junit4:junit4]   2> 10691 T338 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 10691 T427 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:30527. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 10692 T427 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:30527, initiating session
[junit4:junit4]   2> 10692 T340 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:53134
[junit4:junit4]   2> 10693 T340 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:53134
[junit4:junit4]   2> 10694 T342 oazs.ZooKeeperServer.finishSessionInit Established session 0x13b9ce44897000c with negotiated timeout 8000 for client /140.211.11.196:53134
[junit4:junit4]   2> 10694 T427 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:30527, sessionid = 0x13b9ce44897000c, negotiated timeout = 8000
[junit4:junit4]   2> 10695 T428 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f38fd40 name:ZooKeeperConnection Watcher:127.0.0.1:30527/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 10695 T338 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 10697 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce44897000c type:create cxid:0x1 zxid:0x97 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 10699 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce44897000c type:create cxid:0x2 zxid:0x98 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 10701 T338 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15936_
[junit4:junit4]   2> 10701 T343 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13b9ce44897000c type:delete cxid:0x4 zxid:0x99 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:15936_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:15936_
[junit4:junit4]   2> 10709 T338 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15936_
[junit4:junit4]   2> 10713 T379 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> 10714 T394 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 10714 T360 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 10714 T411 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 10715 T411 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> 10714 T394 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> 10714 T366 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 10715 T338 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 0
[junit4:junit4]   2> 10714 T360 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> 10716 T366 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> 10716 T379 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 10716 T338 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 10717 T338 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 0
[junit4:junit4]   2> 10717 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 10718 T338 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 10718 T338 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 10719 T338 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 10720 T338 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 10720 T338 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 10721 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=0&connTimeout=0&retry=false
[junit4:junit4]   2> 10741 T338 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 10751 T429 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/collection1
[junit4:junit4]   2> 10752 T429 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 10753 T429 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 10753 T429 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 10755 T429 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/collection1/'
[junit4:junit4]   2> 10757 T429 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 10757 T429 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/collection1/lib/README' to classloader
[junit4:junit4]   2> 10841 T429 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 10916 T429 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 11018 T429 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 11029 T429 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C17_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51238_, base_url=http://127.0.0.1:51238}
[junit4:junit4]   2> 11189 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 11189 T397 C17 P51238 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 11190 T397 C17 P51238 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:30536/collection1/. core=collection1
[junit4:junit4]   2> 11190 T397 C17 P51238 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11213 T372 C18 P30536 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16
[junit4:junit4]   2> 11231 T372 C18 P30536 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 11233 T372 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 11237 T372 C18 P30536 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11238 T372 C18 P30536 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11242 T372 C18 P30536 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 11243 T372 C18 P30536 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 11245 T372 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 11246 T372 C18 P30536 oass.SolrIndexSearcher.<init> Opening Searcher@19e502d8 realtime
[junit4:junit4]   2> 11246 T372 C18 P30536 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 11247 T372 C18 P30536 /update {waitSearcher=true&openSearcher=false&commit=true&commit_end_point=true&wt=javabin&softCommit=false&version=2} {commit=} 0 41
[junit4:junit4]   2> 11249 T397 C17 P51238 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 11250 T397 C17 P51238 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4]   2> 11282 T397 C17 P51238 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 11288 T373 C18 P30536 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 11289 T373 C18 P30536 REQ /replication {command=indexversion&wt=javabin&qt=/replication&version=2} status=0 QTime=4 
[junit4:junit4]   2> 11291 T397 C17 P51238 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 11291 T397 C17 P51238 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 11291 T397 C17 P51238 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 11295 T373 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 11297 T373 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index
[junit4:junit4]   2> 11297 T373 C18 P30536 REQ /replication {command=filelist&generation=2&wt=javabin&qt=/replication&version=2} status=0 QTime=3 
[junit4:junit4]   2> 11299 T397 C17 P51238 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 11302 T397 C17 P51238 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017 forceNew:false
[junit4:junit4]   2> 11302 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11304 T397 C17 P51238 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65c88d95) fullCopy=true
[junit4:junit4]   2> 11322 T373 C18 P30536 REQ /replication {file=segments_2&command=filecontent&checksum=true&generation=2&qt=/replication&wt=filestream} status=0 QTime=6 
[junit4:junit4]   2> 11330 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index
[junit4:junit4]   2> 11331 T397 C17 P51238 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 11331 T397 C17 P51238 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20121215044836017
[junit4:junit4]   2> 11334 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11335 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11335 T397 C17 P51238 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017
[junit4:junit4]   2> 11340 T397 C17 P51238 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65c88d95),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 11341 T397 C17 P51238 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 11343 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11349 T397 C17 P51238 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 11349 T397 C17 P51238 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 11350 T397 C17 P51238 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 11351 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017
[junit4:junit4]   2> 11352 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11357 T397 C17 P51238 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65c88d95),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 11358 T397 C17 P51238 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 11358 T397 C17 P51238 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 11359 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11359 T397 C17 P51238 oass.SolrIndexSearcher.<init> Opening Searcher@348d20a4 main
[junit4:junit4]   2> 11362 T396 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@348d20a4 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 11362 T396 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index
[junit4:junit4]   2> 11363 T397 C17 P51238 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 11366 T397 C17 P51238 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65c88d95),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65c88d95),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 11367 T397 C17 P51238 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 11368 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2
[junit4:junit4]   2> 11368 T397 C17 P51238 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 11369 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index.20121215044836017
[junit4:junit4]   2> 11369 T397 C17 P51238 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty2/index
[junit4:junit4]   2> 11369 T397 C17 P51238 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 11369 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 11370 T397 C17 P51238 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 11370 T397 C17 P51238 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11372 T397 C17 P51238 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 11484 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11485 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:51238_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:51238"}
[junit4:junit4]   2> 11504 T394 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> 11504 T428 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> 11504 T411 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> 11505 T379 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> 11505 T360 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> 11505 T366 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> 11866 T429 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 11878 T429 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 11883 T429 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 11904 T429 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 11921 T429 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 11926 T429 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 11927 T429 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 11929 T429 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1355546914996/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/
[junit4:junit4]   2> 11929 T429 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2716630b
[junit4:junit4]   2> 11930 T429 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 11931 T429 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4 forceNew:false
[junit4:junit4]   2> 11932 T429 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4
[junit4:junit4]   2> 11932 T429 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index/
[junit4:junit4]   2> 11933 T429 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 11933 T429 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index forceNew:false
[junit4:junit4]   2> 11939 T429 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@65770081),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11939 T429 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11940 T429 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index
[junit4:junit4]   2> 11940 T429 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 11943 T429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 11943 T429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 11944 T429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 11944 T429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 11945 T429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 11945 T429 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 11946 T429 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 11947 T429 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 11949 T429 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 11950 T429 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 11952 T429 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 11952 T429 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 11953 T429 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 11954 T429 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 11954 T429 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 11956 T429 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 11957 T429 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11958 T429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11960 T429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11961 T429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11962 T429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11964 T429 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11965 T429 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11966 T429 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 11968 T429 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 11969 T429 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 11982 T429 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 11997 T429 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 12000 T429 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> 12003 T429 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4
[junit4:junit4]   2> 12005 T429 oass.SolrIndexSearcher.<init> Opening Searcher@4eeeca00 main
[junit4:junit4]   2> 12006 T429 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 12006 T429 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 12007 T429 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 12014 T429 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 12088 T431 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4eeeca00 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 12094 T429 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 12094 T429 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12515 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12516 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:15936_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:15936"}
[junit4:junit4]   2> 12517 T361 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 12517 T361 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 12530 T411 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> 12530 T379 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> 12530 T366 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> 12530 T360 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> 12530 T394 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> 12530 T428 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> 12597 T429 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 12597 T429 oasc.ZkController.register Register shard - core:collection1 address:http://127.0.0.1:15936 shardId:shard1
[junit4:junit4]   2> 12605 T429 oasc.ZkController.register We are http://127.0.0.1:15936/collection1/ and leader is http://127.0.0.1:30536/collection1/
[junit4:junit4]   2> 12606 T429 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15936
[junit4:junit4]   2> 12606 T429 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 12606 T429 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C20 name=collection1 org.apache.solr.core.SolrCore@e127a3f url=http://127.0.0.1:15936/collection1 node=127.0.0.1:15936_
[junit4:junit4]   2> 12607 T432 C20 P15936 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 12608 T432 C20 P15936 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 12608 T429 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12608 T432 C20 P15936 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 12609 T432 C20 P15936 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12610 T338 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   2> 12610 T338 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12611 T432 C20 P15936 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:30536/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 12612 T338 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12612 T432 C20 P15936 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:15936 START replicas=[http://127.0.0.1:30536/collection1/] nUpdates=100
[junit4:junit4]   2> 12613 T432 C20 P15936 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 12613 T432 C20 P15936 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 12613 T432 C20 P15936 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 12614 T432 C20 P15936 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12616 T369 C18 P30536 REQ /get {distrib=false&qt=/get&wt=javabin&version=2&getVersions=100} status=0 QTime=0 
[junit4:junit4]   2> 12633 T338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12636 T338 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 12636 T338 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 12638 T338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13037 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13038 T361 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":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:15936_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:15936"}
[junit4:junit4]   2> 13046 T428 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> 13046 T394 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> 13046 T411 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> 13046 T366 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> 13046 T360 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> 13046 T379 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>  C19_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:16867_, base_url=http://127.0.0.1:16867}
[junit4:junit4]   2> 13284 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 13284 T414 C19 P16867 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 13284 T414 C19 P16867 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:30536/collection1/. core=collection1
[junit4:junit4]   2> 13285 T414 C19 P16867 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13299 T375 C18 P30536 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 13304 T375 C18 P30536 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 13305 T375 C18 P30536 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 13305 T375 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 13306 T375 C18 P30536 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 13306 T375 C18 P30536 /update {waitSearcher=true&openSearcher=false&commit=true&commit_end_point=true&wt=javabin&softCommit=false&version=2} {commit=} 0 8
[junit4:junit4]   2> 13309 T414 C19 P16867 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 13309 T414 C19 P16867 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 13313 T373 C18 P30536 REQ /replication {command=indexversion&wt=javabin&qt=/replication&version=2} status=0 QTime=1 
[junit4:junit4]   2> 13314 T414 C19 P16867 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4]   2> 13314 T414 C19 P16867 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 13314 T414 C19 P16867 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 13318 T373 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 13319 T373 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index
[junit4:junit4]   2> 13319 T373 C18 P30536 REQ /replication {command=filelist&generation=3&wt=javabin&qt=/replication&version=2} status=0 QTime=2 
[junit4:junit4]   2> 13320 T414 C19 P16867 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 13322 T414 C19 P16867 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038 forceNew:false
[junit4:junit4]   2> 13322 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13323 T414 C19 P16867 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038 lockFactory=org.apache.lucene.store.NativeFSLockFactory@211da3a4) fullCopy=true
[junit4:junit4]   2> 13327 T373 C18 P30536 REQ /replication {file=segments_3&command=filecontent&checksum=true&generation=3&qt=/replication&wt=filestream} status=0 QTime=1 
[junit4:junit4]   2> 13329 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index
[junit4:junit4]   2> 13329 T414 C19 P16867 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 13330 T414 C19 P16867 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20121215044838038
[junit4:junit4]   2> 13332 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13333 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13333 T414 C19 P16867 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038
[junit4:junit4]   2> 13337 T414 C19 P16867 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038 lockFactory=org.apache.lucene.store.NativeFSLockFactory@211da3a4),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 13337 T414 C19 P16867 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 13339 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13339 T414 C19 P16867 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 13339 T414 C19 P16867 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 13340 T414 C19 P16867 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 13341 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038
[junit4:junit4]   2> 13341 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13345 T414 C19 P16867 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038 lockFactory=org.apache.lucene.store.NativeFSLockFactory@211da3a4),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 13345 T414 C19 P16867 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 13346 T414 C19 P16867 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 13346 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13347 T414 C19 P16867 oass.SolrIndexSearcher.<init> Opening Searcher@76584c46 main
[junit4:junit4]   2> 13349 T413 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@76584c46 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4]   2> 13350 T413 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index
[junit4:junit4]   2> 13351 T414 C19 P16867 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 13354 T414 C19 P16867 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038 lockFactory=org.apache.lucene.store.NativeFSLockFactory@211da3a4),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038 lockFactory=org.apache.lucene.store.NativeFSLockFactory@211da3a4),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 13354 T414 C19 P16867 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 13355 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3
[junit4:junit4]   2> 13356 T414 C19 P16867 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 13356 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index.20121215044838038
[junit4:junit4]   2> 13356 T414 C19 P16867 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty3/index
[junit4:junit4]   2> 13357 T414 C19 P16867 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 13357 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 13357 T414 C19 P16867 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 13357 T414 C19 P16867 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 13360 T414 C19 P16867 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 13558 T361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13559 T361 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:16867_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:16867"}
[junit4:junit4]   2> 13573 T428 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> 13573 T411 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> 13573 T379 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> 13573 T394 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> 13573 T360 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> 13573 T366 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> 13640 T338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14642 T338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C20_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:15936_, base_url=http://127.0.0.1:15936}
[junit4:junit4]   2> 15635 T432 C20 P15936 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 15635 T432 C20 P15936 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 15636 T432 C20 P15936 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:30536/collection1/. core=collection1
[junit4:junit4]   2> 15636 T432 C20 P15936 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 15644 T338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15655 T370 C18 P30536 oasu.DirectUpdateHandler2.commit start commit{flags=0,_version_=0,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 15680 T370 C18 P30536 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25260d76),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 15681 T370 C18 P30536 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 15681 T370 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 15682 T370 C18 P30536 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 15682 T370 C18 P30536 /update {waitSearcher=true&openSearcher=false&commit=true&commit_end_point=true&wt=javabin&softCommit=false&version=2} {commit=} 0 27
[junit4:junit4]   2> 15684 T432 C20 P15936 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 15685 T432 C20 P15936 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 15687 T373 C18 P30536 REQ /replication {command=indexversion&wt=javabin&qt=/replication&version=2} status=0 QTime=0 
[junit4:junit4]   2> 15689 T432 C20 P15936 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4]   2> 15689 T432 C20 P15936 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 15689 T432 C20 P15936 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 15691 T373 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1
[junit4:junit4]   2> 15692 T373 C18 P30536 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty1/index
[junit4:junit4]   2> 15693 T373 C18 P30536 REQ /replication {command=filelist&generation=4&wt=javabin&qt=/replication&version=2} status=0 QTime=2 
[junit4:junit4]   2> 15694 T432 C20 P15936 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 15695 T432 C20 P15936 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index.20121215044840411 forceNew:false
[junit4:junit4]   2> 15696 T432 C20 P15936 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4
[junit4:junit4]   2> 15696 T432 C20 P15936 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index.20121215044840411 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f9e25dc) fullCopy=true
[junit4:junit4]   2> 15700 T373 C18 P30536 REQ /replication {file=segments_4&command=filecontent&checksum=true&generation=4&qt=/replication&wt=filestream} status=0 QTime=0 
[junit4:junit4]   2> 15703 T432 C20 P15936 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index
[junit4:junit4]   2> 15703 T432 C20 P15936 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 15704 T432 C20 P15936 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20121215044840411
[junit4:junit4]   2> 15705 T432 C20 P15936 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4
[junit4:junit4]   2> 15706 T432 C20 P15936 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4
[junit4:junit4]   2> 15706 T432 C20 P15936 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1355546904722/jetty4/index.20121215044840411
[junit4:juni

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

workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-solrj/classes/java:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/classes/java:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/analysis/common/lucene-analyzers-common-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/analysis/kuromoji/lucene-analyzers-kuromoji-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/analysis/phonetic/lucene-analyzers-phonetic-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/highlighter/lucene-highlighter-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/memory/lucene-memory-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/misc/lucene-misc-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/spatial/lucene-spatial-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/suggest/lucene-suggest-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/grouping/lucene-grouping-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/queries/lucene-queries-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/queryparser/lucene-queryparser-5.0-SNAPSHOT.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/cglib-nodep-2.2.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/commons-cli-1.2.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/commons-codec-1.7.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/commons-fileupload-1.2.1.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/commons-lang-2.6.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/easymock-3.0.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/guava-13.0.1.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/javax.servlet-api-3.0.1.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/metrics-core-2.1.2.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/objenesis-1.2.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/core/lib/spatial4j-0.3.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/commons-io-2.1.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/httpclient-4.1.3.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/httpcore-4.1.4.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/httpmime-4.1.3.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/jcl-over-slf4j-1.6.4.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/log4j-over-slf4j-1.6.4.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/slf4j-api-1.6.4.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/slf4j-jdk14-1.6.4.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/wstx-asl-3.2.7.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/solrj/lib/zookeeper-3.4.5.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-continuation-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-deploy-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-http-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-io-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-jmx-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-security-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-server-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-servlet-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-util-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-webapp-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/jetty-xml-8.1.8.v20121106.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/lib/servlet-api-3.0.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/example-DIH/solr/db/lib/derby-10.9.1.0.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/example/example-DIH/solr/db/lib/hsqldb-1.8.0.10.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/build/core/classes/java:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/test-framework/lib/junit-4.10.jar:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/test-framework/lib/randomizedtesting-runner-2.0.5.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-launcher.jar:/home/hudson/.ant/lib/ivy-2.2.0.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-regexp.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-junit.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-bsf.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-commons-net.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-antlr.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-log4j.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-commons-logging.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-xalan2.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-oro.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-junit4.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-netrexx.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-swing.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-javamail.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-jsch.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-jmf.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-bcel.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-jai.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-testutil.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-apache-resolver.jar:/home/hudson/hudson-slave/tools/Ant/ant-1.8.2/lib/ant-jdepend.jar:/usr/local/openjdk7/lib/tools.jar:/home/hudson/.ivy2/cache/com.carrotsearch.randomizedtesting/junit4-ant/jars/junit4-ant-2.0.5.jar -ea:org.apache.lucene... -ea:org.apache.solr... com.carrotsearch.ant.tasks.junit4.slave.SlaveMainSafe -eventsfile /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/junit4-J0-20121215_044321_172.events @/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/junit4-J0-20121215_044321_172.suites
[junit4:junit4] ERROR: JVM J0 ended with an exception: Forked process returned with error code: 134 Very likely a JVM crash.  Process output piped in logs above.
[junit4:junit4] 	at com.carrotsearch.ant.tasks.junit4.JUnit4.executeSlave(JUnit4.java:1206)
[junit4:junit4] 	at com.carrotsearch.ant.tasks.junit4.JUnit4.access$000(JUnit4.java:65)
[junit4:junit4] 	at com.carrotsearch.ant.tasks.junit4.JUnit4$2.call(JUnit4.java:813)
[junit4:junit4] 	at com.carrotsearch.ant.tasks.junit4.JUnit4$2.call(JUnit4.java:810)
[junit4:junit4] 	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[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)

BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:353: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:178: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:438: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1176: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:839: At least one slave process threw an exception, first: Forked process returned with error code: 134 Very likely a JVM crash.  Process output piped in logs above.

Total time: 46 minutes 37 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message