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 # 3777 - Still Failing
Date Sat, 02 Mar 2013 04:12:17 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3777/

4 tests failed.
FAILED:  junit.framework.TestSuite.org.apache.solr.cloud.RecoveryZkTest

Error Message:
Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=2262, name=coreLoadExecutor-939-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.

Stack Trace:
com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=2262, name=coreLoadExecutor-939-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
	at java.lang.Thread.getStackTrace(Thread.java:1567)
	at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
	at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
	at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
	at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
	at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
	at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:33)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:267)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:223)
	at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
	at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:733)
	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
	at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:868)
	at org.apache.solr.core.CoreContainer.create(CoreContainer.java:951)
	at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
	at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:569)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
	at java.util.concurrent.FutureTask.run(FutureTask.java:166)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@30db6747 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e71cb56; maxCacheMB=0.5576171875 maxMergeSizeMB=0.19921875))
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
	at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	... 1 more


FAILED:  junit.framework.TestSuite.org.apache.solr.cloud.RecoveryZkTest

Error Message:
Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=2264, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.

Stack Trace:
com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=2264, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
	at java.lang.Thread.getStackTrace(Thread.java:1567)
	at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
	at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
	at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
	at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
	at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
	at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:33)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:267)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:223)
	at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
	at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
	at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
	at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
	at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@547c839 lockFactory=org.apache.lucene.store.NativeFSLockFactory@37e28415; maxCacheMB=0.5576171875 maxMergeSizeMB=0.19921875))
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
	at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)


REGRESSION:  org.apache.solr.cloud.SyncSliceTest.testDistribSearch

Error Message:
Test Setup Failure: shard1 should have just been set up to be inconsistent - but it's still consistent. Leader:http://127.0.0.1:43359/collection1skip list:[CloudJettyRunner [url=http://127.0.0.1:43364/collection1], CloudJettyRunner [url=http://127.0.0.1:43373/collection1]]

Stack Trace:
java.lang.AssertionError: Test Setup Failure: shard1 should have just been set up to be inconsistent - but it's still consistent. Leader:http://127.0.0.1:43359/collection1skip list:[CloudJettyRunner [url=http://127.0.0.1:43364/collection1], CloudJettyRunner [url=http://127.0.0.1:43373/collection1]]
	at __randomizedtesting.SeedInfo.seed([65B4AE6394B1306E:E452207BE3EE5052]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.junit.Assert.assertTrue(Assert.java:43)
	at org.junit.Assert.assertNotNull(Assert.java:526)
	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:212)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java: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)


FAILED:  org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch

Error Message:
No registered leader was found, collection:collection1 slice:shard1

Stack Trace:
org.apache.solr.common.SolrException: No registered leader was found, collection:collection1 slice:shard1
	at __randomizedtesting.SeedInfo.seed([65B4AE6394B1306E:E452207BE3EE5052]:0)
	at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:430)
	at org.apache.solr.cloud.BasicDistributedZk2Test.brindDownShardIndexSomeDocsAndRecover(BasicDistributedZk2Test.java:295)
	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:116)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java: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 8937 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4]   2> 0 T272 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 6 T272 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/J1/./solrtest-SyncSliceTest-1362196431461
[junit4:junit4]   2> 8 T272 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 8 T273 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 12 T273 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 12 T273 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 12 T273 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 13 T273 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 14 T273 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 109 T272 oasc.ZkTestServer.run start zk server on port:43327
[junit4:junit4]   2> 110 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6578553b
[junit4:junit4]   2> 111 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 111 T278 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 113 T278 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 113 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43328
[junit4:junit4]   2> 114 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43328
[junit4:junit4]   2> 114 T276 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 117 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0000 with negotiated timeout 10000 for client /140.211.11.196:43328
[junit4:junit4]   2> 117 T278 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0000, negotiated timeout = 10000
[junit4:junit4]   2> 118 T279 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6578553b name:ZooKeeperConnection Watcher:127.0.0.1:43327 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 119 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 119 T272 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 124 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e0000
[junit4:junit4]   2> 125 T279 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 125 T272 oaz.ZooKeeper.close Session: 0x13d293c026e0000 closed
[junit4:junit4]   2> 126 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43328 which had sessionid 0x13d293c026e0000
[junit4:junit4]   2> 127 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@42299fb
[junit4:junit4]   2> 128 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 129 T280 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 129 T280 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 130 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43329
[junit4:junit4]   2> 130 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43329
[junit4:junit4]   2> 148 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0001 with negotiated timeout 10000 for client /140.211.11.196:43329
[junit4:junit4]   2> 148 T280 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0001, negotiated timeout = 10000
[junit4:junit4]   2> 149 T281 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@42299fb name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 149 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 150 T272 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 156 T272 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 163 T272 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 169 T272 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 174 T272 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-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 176 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 223 T272 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> 226 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 332 T272 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> 333 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 338 T272 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> 339 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 349 T272 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> 350 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 355 T272 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> 356 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 365 T272 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> 367 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 375 T272 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> 376 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 408 T272 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> 409 T272 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 418 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e0001
[junit4:junit4]   2> 421 T281 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 422 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43329 which had sessionid 0x13d293c026e0001
[junit4:junit4]   2> 421 T272 oaz.ZooKeeper.close Session: 0x13d293c026e0001 closed
[junit4:junit4]   2> 782 T272 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 787 T272 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43330
[junit4:junit4]   2> 788 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 788 T272 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 789 T272 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/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877
[junit4:junit4]   2> 790 T272 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/solr.xml
[junit4:junit4]   2> 790 T272 oasc.CoreContainer.<init> New CoreContainer 1558686721
[junit4:junit4]   2> 791 T272 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/'
[junit4:junit4]   2> 792 T272 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/'
[junit4:junit4]   2> 900 T272 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 901 T272 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 902 T272 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 902 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 903 T272 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 903 T272 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 904 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 904 T272 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 905 T272 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 906 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 932 T272 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 1072 T272 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43327/solr
[junit4:junit4]   2> 1072 T272 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 1073 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2d1a8b1
[junit4:junit4]   2> 1074 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1075 T291 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 1076 T291 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 1076 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43331
[junit4:junit4]   2> 1077 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43331
[junit4:junit4]   2> 1102 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0002 with negotiated timeout 20000 for client /140.211.11.196:43331
[junit4:junit4]   2> 1102 T291 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0002, negotiated timeout = 20000
[junit4:junit4]   2> 1103 T292 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d1a8b1 name:ZooKeeperConnection Watcher:127.0.0.1:43327 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1103 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1105 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e0002
[junit4:junit4]   2> 1142 T292 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 1142 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43331 which had sessionid 0x13d293c026e0002
[junit4:junit4]   2> 1142 T272 oaz.ZooKeeper.close Session: 0x13d293c026e0002 closed
[junit4:junit4]   2> 1143 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 1163 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3d9f1363
[junit4:junit4]   2> 1165 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 1165 T293 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 1166 T293 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 1166 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43332
[junit4:junit4]   2> 1167 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43332
[junit4:junit4]   2> 1170 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0003 with negotiated timeout 20000 for client /140.211.11.196:43332
[junit4:junit4]   2> 1170 T293 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0003, negotiated timeout = 20000
[junit4:junit4]   2> 1170 T294 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d9f1363 name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 1171 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 1205 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1235 T272 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 1242 T272 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43330_
[junit4:junit4]   2> 1243 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43330_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43330_
[junit4:junit4]   2> 1245 T272 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43330_
[junit4:junit4]   2> 1295 T272 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 1372 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 1378 T272 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 1434 T272 oasc.Overseer.start Overseer (id=89272905332817923-127.0.0.1:43330_-n_0000000000) starting
[junit4:junit4]   2> 1436 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1466 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1468 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1469 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1506 T296 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 1507 T272 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 1526 T272 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 1533 T295 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 1538 T297 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/collection1
[junit4:junit4]   2> 1539 T297 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 1539 T297 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 1540 T297 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 1541 T297 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/collection1/'
[junit4:junit4]   2> 1543 T297 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/collection1/lib/README' to classloader
[junit4:junit4]   2> 1543 T297 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 1610 T297 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 1676 T297 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1778 T297 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 1790 T297 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 2520 T297 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 2540 T297 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 2546 T297 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 2570 T297 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 2576 T297 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 2581 T297 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 2583 T297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 2583 T297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 2584 T297 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 2585 T297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 2585 T297 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 2586 T297 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362196431877/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/
[junit4:junit4]   2> 2586 T297 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@27d0e91
[junit4:junit4]   2> 2587 T297 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 2588 T297 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data forceNew:false
[junit4:junit4]   2> 2588 T297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data
[junit4:junit4]   2> 2589 T297 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/index/
[junit4:junit4]   2> 2590 T297 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 2590 T297 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/index forceNew:false
[junit4:junit4]   2> 2594 T297 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@24d4969f lockFactory=org.apache.lucene.store.NativeFSLockFactory@340408e4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 2594 T297 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 2596 T297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/index
[junit4:junit4]   2> 2597 T297 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 2598 T297 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 2598 T297 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 2599 T297 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 2599 T297 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 2600 T297 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 2600 T297 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 2600 T297 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 2601 T297 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 2620 T297 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 2629 T297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data
[junit4:junit4]   2> 2629 T297 oass.SolrIndexSearcher.<init> Opening Searcher@77e09ce6 main
[junit4:junit4]   2> 2630 T297 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/tlog
[junit4:junit4]   2> 2631 T297 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 2631 T297 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 2635 T298 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77e09ce6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 2637 T297 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 2637 T297 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 2638 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 3040 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3041 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "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:43330_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43330"}
[junit4:junit4]   2> 3041 T295 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 3041 T295 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 3042 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 3103 T294 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> 3662 T297 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 3662 T297 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43330 collection:control_collection shard:shard1
[junit4:junit4]   2> 3663 T297 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 3855 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:delete cxid:0x72 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> 3859 T297 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 3860 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3895 T297 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 3895 T297 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 3896 T297 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43330/collection1/
[junit4:junit4]   2> 3896 T297 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 3896 T297 oasc.SyncStrategy.syncToMe http://127.0.0.1:43330/collection1/ has no replicas
[junit4:junit4]   2> 3897 T297 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43330/collection1/
[junit4:junit4]   2> 3897 T297 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 3931 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4613 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4657 T294 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> 4716 T297 oasc.ZkController.register We are http://127.0.0.1:43330/collection1/ and leader is http://127.0.0.1:43330/collection1/
[junit4:junit4]   2> 4716 T297 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43330
[junit4:junit4]   2> 4716 T297 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 4717 T297 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 4717 T297 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 4720 T297 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4721 T272 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 4722 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 4723 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 4747 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 4749 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@47b03d65
[junit4:junit4]   2> 4750 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4751 T300 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4752 T300 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 4752 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43351
[junit4:junit4]   2> 4753 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43351
[junit4:junit4]   2> 4754 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0004 with negotiated timeout 10000 for client /140.211.11.196:43351
[junit4:junit4]   2> 4754 T300 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0004, negotiated timeout = 10000
[junit4:junit4]   2> 4755 T301 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47b03d65 name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4755 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4757 T272 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4759 T272 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 4987 T272 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 4990 T272 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43352
[junit4:junit4]   2> 4991 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 4991 T272 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 4992 T272 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/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213
[junit4:junit4]   2> 4993 T272 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/solr.xml
[junit4:junit4]   2> 4993 T272 oasc.CoreContainer.<init> New CoreContainer 1071731308
[junit4:junit4]   2> 4994 T272 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/'
[junit4:junit4]   2> 4995 T272 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/'
[junit4:junit4]   2> 5081 T272 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 5082 T272 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 5082 T272 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 5083 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 5083 T272 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 5084 T272 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 5084 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 5085 T272 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 5086 T272 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 5086 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 5112 T272 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 5132 T272 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43327/solr
[junit4:junit4]   2> 5133 T272 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 5134 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2cef10dc
[junit4:junit4]   2> 5135 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 5135 T311 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 5137 T311 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 5137 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43353
[junit4:junit4]   2> 5137 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43353
[junit4:junit4]   2> 5139 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0005 with negotiated timeout 20000 for client /140.211.11.196:43353
[junit4:junit4]   2> 5139 T311 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0005, negotiated timeout = 20000
[junit4:junit4]   2> 5140 T312 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cef10dc name:ZooKeeperConnection Watcher:127.0.0.1:43327 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 5140 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 5143 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e0005
[junit4:junit4]   2> 5152 T312 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 5152 T272 oaz.ZooKeeper.close Session: 0x13d293c026e0005 closed
[junit4:junit4]   2> 5152 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43353 which had sessionid 0x13d293c026e0005
[junit4:junit4]   2> 5153 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 5167 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7ee61e1f
[junit4:junit4]   2> 5168 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 5168 T313 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 5169 T313 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 5170 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43354
[junit4:junit4]   2> 5170 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43354
[junit4:junit4]   2> 5176 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0006 with negotiated timeout 20000 for client /140.211.11.196:43354
[junit4:junit4]   2> 5176 T313 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0006, negotiated timeout = 20000
[junit4:junit4]   2> 5176 T314 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ee61e1f name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 5177 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 5178 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 5224 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 5227 T272 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 6185 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6186 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43330_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43330"}
[junit4:junit4]   2> 6211 T294 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> 6211 T314 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> 6211 T301 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> 6230 T272 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43352_
[junit4:junit4]   2> 6232 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0006 type:delete cxid:0xb zxid:0x4f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43352_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43352_
[junit4:junit4]   2> 6233 T272 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43352_
[junit4:junit4]   2> 6245 T294 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 6245 T314 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 6245 T301 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 6247 T294 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 6248 T301 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 6248 T314 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 6257 T315 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/collection1
[junit4:junit4]   2> 6257 T315 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 6258 T315 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 6259 T315 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 6261 T315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/collection1/'
[junit4:junit4]   2> 6263 T315 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/collection1/lib/README' to classloader
[junit4:junit4]   2> 6264 T315 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 6327 T315 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 6403 T315 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 6504 T315 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 6514 T315 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 7287 T315 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 7301 T315 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 7305 T315 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 7330 T315 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 7337 T315 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 7343 T315 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 7344 T315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 7345 T315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 7345 T315 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 7346 T315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 7347 T315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 7347 T315 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362196436213/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/
[junit4:junit4]   2> 7348 T315 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@27d0e91
[junit4:junit4]   2> 7348 T315 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 7349 T315 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1 forceNew:false
[junit4:junit4]   2> 7350 T315 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 7350 T315 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index/
[junit4:junit4]   2> 7351 T315 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 7352 T315 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index forceNew:false
[junit4:junit4]   2> 7355 T315 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 7356 T315 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 7357 T315 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index
[junit4:junit4]   2> 7360 T315 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 7360 T315 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 7361 T315 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 7362 T315 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 7363 T315 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 7363 T315 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 7364 T315 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 7365 T315 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 7365 T315 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 7385 T315 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 7393 T315 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 7394 T315 oass.SolrIndexSearcher.<init> Opening Searcher@5998a422 main
[junit4:junit4]   2> 7394 T315 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/tlog
[junit4:junit4]   2> 7396 T315 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 7396 T315 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 7402 T316 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5998a422 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 7406 T315 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 7406 T315 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7718 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7719 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "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:43352_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43352"}
[junit4:junit4]   2> 7720 T295 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4]   2> 7720 T295 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 7726 T294 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> 7726 T301 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> 7726 T314 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> 8462 T315 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 8462 T315 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43352 collection:collection1 shard:shard1
[junit4:junit4]   2> 8463 T315 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 8492 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0006 type:delete cxid:0x48 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 8493 T315 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 8494 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0006 type:create cxid:0x49 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8525 T315 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 8526 T315 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 8526 T315 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43352/collection1/
[junit4:junit4]   2> 8526 T315 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 8527 T315 oasc.SyncStrategy.syncToMe http://127.0.0.1:43352/collection1/ has no replicas
[junit4:junit4]   2> 8527 T315 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43352/collection1/
[junit4:junit4]   2> 8527 T315 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 8546 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0006 type:create cxid:0x53 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9239 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9267 T294 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> 9268 T301 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> 9268 T314 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> 9271 T315 oasc.ZkController.register We are http://127.0.0.1:43352/collection1/ and leader is http://127.0.0.1:43352/collection1/
[junit4:junit4]   2> 9271 T315 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43352
[junit4:junit4]   2> 9271 T315 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 9272 T315 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 9272 T315 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9284 T315 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9286 T272 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 9286 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 9287 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 9562 T272 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 9566 T272 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43359
[junit4:junit4]   2> 9567 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 9567 T272 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 9568 T272 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/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759
[junit4:junit4]   2> 9569 T272 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/solr.xml
[junit4:junit4]   2> 9569 T272 oasc.CoreContainer.<init> New CoreContainer 703142356
[junit4:junit4]   2> 9570 T272 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/'
[junit4:junit4]   2> 9571 T272 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/'
[junit4:junit4]   2> 9654 T272 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 9655 T272 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 9655 T272 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 9656 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 9657 T272 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 9657 T272 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 9658 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 9658 T272 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 9659 T272 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 9659 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 9686 T272 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 9708 T272 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43327/solr
[junit4:junit4]   2> 9709 T272 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 9710 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1725c61
[junit4:junit4]   2> 9711 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 9711 T327 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 9712 T327 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 9713 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43360
[junit4:junit4]   2> 9713 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43360
[junit4:junit4]   2> 9715 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0007 with negotiated timeout 20000 for client /140.211.11.196:43360
[junit4:junit4]   2> 9715 T327 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0007, negotiated timeout = 20000
[junit4:junit4]   2> 9716 T328 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1725c61 name:ZooKeeperConnection Watcher:127.0.0.1:43327 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 9716 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 9718 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e0007
[junit4:junit4]   2> 9719 T328 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 9719 T272 oaz.ZooKeeper.close Session: 0x13d293c026e0007 closed
[junit4:junit4]   2> 9719 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43360 which had sessionid 0x13d293c026e0007
[junit4:junit4]   2> 9720 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 9734 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@18f5567f
[junit4:junit4]   2> 9735 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 9735 T329 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 9736 T329 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 9736 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43361
[junit4:junit4]   2> 9737 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43361
[junit4:junit4]   2> 9738 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0008 with negotiated timeout 20000 for client /140.211.11.196:43361
[junit4:junit4]   2> 9739 T329 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0008, negotiated timeout = 20000
[junit4:junit4]   2> 9739 T330 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18f5567f name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 9739 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 9741 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9742 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9753 T272 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 10757 T272 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43359_
[junit4:junit4]   2> 10759 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e0008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43359_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43359_
[junit4:junit4]   2> 10767 T272 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43359_
[junit4:junit4]   2> 10789 T314 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> 10789 T294 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> 10790 T301 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> 10790 T330 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10792 T314 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10792 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10793 T301 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10793 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43352_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43352"}
[junit4:junit4]   2> 10814 T331 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/collection1
[junit4:junit4]   2> 10814 T331 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 10831 T314 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> 10831 T330 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> 10831 T331 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 10831 T301 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> 10832 T331 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 10835 T331 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/collection1/'
[junit4:junit4]   2> 10836 T331 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/collection1/lib/README' to classloader
[junit4:junit4]   2> 10836 T294 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 10837 T294 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> 10837 T331 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 10891 T331 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 10989 T331 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 11090 T331 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 11099 T331 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 11823 T331 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 11838 T331 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 11843 T331 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 11867 T331 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 11874 T331 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 11880 T331 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 11881 T331 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 11882 T331 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 11882 T331 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 11883 T331 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 11884 T331 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 11884 T331 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362196440759/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/
[junit4:junit4]   2> 11885 T331 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@27d0e91
[junit4:junit4]   2> 11885 T331 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 11886 T331 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2 forceNew:false
[junit4:junit4]   2> 11887 T331 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 11887 T331 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index/
[junit4:junit4]   2> 11888 T331 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 11889 T331 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index forceNew:false
[junit4:junit4]   2> 11893 T331 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4036a060 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c750751),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11893 T331 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11894 T331 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index
[junit4:junit4]   2> 11898 T331 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 11898 T331 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 11899 T331 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 11900 T331 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 11901 T331 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 11901 T331 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 11902 T331 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 11903 T331 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 11903 T331 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 11922 T331 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 11932 T331 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 11932 T331 oass.SolrIndexSearcher.<init> Opening Searcher@1c572ca0 main
[junit4:junit4]   2> 11933 T331 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/tlog
[junit4:junit4]   2> 11942 T331 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 11942 T331 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 11949 T332 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c572ca0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 11952 T331 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 11952 T331 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12338 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12339 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "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:43359_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43359"}
[junit4:junit4]   2> 12339 T295 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 12340 T295 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 12361 T314 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> 12361 T294 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> 12362 T330 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> 12361 T301 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> 12956 T331 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 12956 T331 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43359 collection:collection1 shard:shard1
[junit4:junit4]   2> 12961 T331 oasc.ZkController.register We are http://127.0.0.1:43359/collection1/ and leader is http://127.0.0.1:43352/collection1/
[junit4:junit4]   2> 12962 T331 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43359
[junit4:junit4]   2> 12962 T331 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 12962 T331 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C21 name=collection1 org.apache.solr.core.SolrCore@19ccda74 url=http://127.0.0.1:43359/collection1 node=127.0.0.1:43359_ C21_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43359_, base_url=http://127.0.0.1:43359}
[junit4:junit4]   2> 12963 T333 C21 P43359 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 12963 T331 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12964 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 12964 T333 C21 P43359 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 12965 T333 C21 P43359 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12965 T272 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12966 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12966 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12967 T333 C21 P43359 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13220 T272 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 13223 T272 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43364
[junit4:junit4]   2> 13224 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 13225 T272 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 13225 T272 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/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442
[junit4:junit4]   2> 13226 T272 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/solr.xml
[junit4:junit4]   2> 13226 T272 oasc.CoreContainer.<init> New CoreContainer 1270145250
[junit4:junit4]   2> 13227 T272 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/'
[junit4:junit4]   2> 13228 T272 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/'
[junit4:junit4]   2> 13313 T272 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 13314 T272 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 13314 T272 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 13315 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 13316 T272 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 13316 T272 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 13317 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 13317 T272 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 13318 T272 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 13318 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 13345 T272 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 13368 T272 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43327/solr
[junit4:junit4]   2> 13369 T272 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 13369 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1a43c7a0
[junit4:junit4]   2> 13370 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13371 T344 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13372 T344 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 13372 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43365
[junit4:junit4]   2> 13373 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43365
[junit4:junit4]   2> 13376 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e0009 with negotiated timeout 20000 for client /140.211.11.196:43365
[junit4:junit4]   2> 13376 T344 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e0009, negotiated timeout = 20000
[junit4:junit4]   2> 13376 T345 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a43c7a0 name:ZooKeeperConnection Watcher:127.0.0.1:43327 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13377 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13378 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e0009
[junit4:junit4]   2> 13390 T345 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 13390 T272 oaz.ZooKeeper.close Session: 0x13d293c026e0009 closed
[junit4:junit4]   2> 13391 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43365 which had sessionid 0x13d293c026e0009
[junit4:junit4]   2> 13392 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 13406 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@21b953c3
[junit4:junit4]   2> 13407 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13407 T346 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13408 T346 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 13408 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43366
[junit4:junit4]   2> 13409 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43366
[junit4:junit4]   2> 13410 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e000a with negotiated timeout 20000 for client /140.211.11.196:43366
[junit4:junit4]   2> 13410 T346 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e000a, negotiated timeout = 20000
[junit4:junit4]   2> 13411 T347 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21b953c3 name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13411 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13413 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e000a type:create cxid:0x1 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13419 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e000a type:create cxid:0x2 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13422 T272 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13868 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13869 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43359_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43359"}
[junit4:junit4]   2> 13897 T294 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> 13898 T301 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> 13898 T330 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> 13898 T347 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> 13897 T314 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> 14425 T272 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43364_
[junit4:junit4]   2> 14427 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e000a type:delete cxid:0xb zxid:0x86 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43364_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43364_
[junit4:junit4]   2> 14435 T272 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43364_
[junit4:junit4]   2> 14457 T314 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> 14457 T294 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> 14457 T301 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> 14457 T347 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14457 T330 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> 14458 T347 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> 14459 T314 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14459 T301 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14460 T294 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14461 T330 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 14467 T348 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/collection1
[junit4:junit4]   2> 14467 T348 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 14468 T348 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 14468 T348 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 14470 T348 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/collection1/'
[junit4:junit4]   2> 14471 T348 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/collection1/lib/README' to classloader
[junit4:junit4]   2> 14472 T348 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 14525 T348 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 14587 T348 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 14688 T348 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 14697 T348 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 15325 T348 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 15338 T348 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 15342 T348 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 15364 T348 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 15370 T348 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 15375 T348 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 15377 T348 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 15378 T348 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 15378 T348 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 15379 T348 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 15380 T348 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 15380 T348 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362196444442/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/
[junit4:junit4]   2> 15380 T348 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@27d0e91
[junit4:junit4]   2> 15381 T348 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 15382 T348 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3 forceNew:false
[junit4:junit4]   2> 15383 T348 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 15383 T348 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index/
[junit4:junit4]   2> 15384 T348 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 15384 T348 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index forceNew:false
[junit4:junit4]   2> 15387 T348 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7eff69f0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bc795ae),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 15388 T348 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 15388 T348 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index
[junit4:junit4]   2> 15391 T348 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 15392 T348 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 15393 T348 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 15394 T348 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 15395 T348 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 15395 T348 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 15396 T348 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 15396 T348 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 15397 T348 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 15411 T348 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 15417 T348 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 15418 T348 oass.SolrIndexSearcher.<init> Opening Searcher@72da1907 main
[junit4:junit4]   2> 15418 T348 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/tlog
[junit4:junit4]   2> 15419 T348 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 15420 T348 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 15426 T349 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72da1907 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 15429 T348 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 15429 T348 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2>  C21_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43359_, base_url=http://127.0.0.1:43359}
[junit4:junit4]   2> 15992 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43352/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 15992 T333 C21 P43359 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43359 START replicas=[http://127.0.0.1:43352/collection1/] nUpdates=100
[junit4:junit4]   2> 15993 T333 C21 P43359 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 15994 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 15994 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 15994 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 15994 T333 C21 P43359 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 15995 T333 C21 P43359 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43352/collection1/. core=collection1
[junit4:junit4]   2> 15995 T333 C21 P43359 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C22 name=collection1 org.apache.solr.core.SolrCore@7f42a80d url=http://127.0.0.1:43352/collection1 node=127.0.0.1:43352_ C22_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43352_, base_url=http://127.0.0.1:43352, leader=true}
[junit4:junit4]   2> 16002 T305 C22 P43352 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 16014 T306 C22 P43352 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 16015 T306 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 16018 T306 C22 P43352 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 16018 T306 C22 P43352 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 16019 T306 C22 P43352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 16020 T306 C22 P43352 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 16020 T306 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 16021 T306 C22 P43352 oass.SolrIndexSearcher.<init> Opening Searcher@6e56c1cc realtime
[junit4:junit4]   2> 16022 T306 C22 P43352 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 16022 T306 C22 P43352 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4]   2> 16023 T333 C21 P43359 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 16023 T333 C21 P43359 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 16026 T307 C22 P43352 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 16027 T307 C22 P43352 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 16028 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 16028 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 16028 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 16031 T307 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 16032 T307 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index
[junit4:junit4]   2> 16032 T307 C22 P43352 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> 16033 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 16034 T333 C21 P43359 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index.20130302025407488 forceNew:false
[junit4:junit4]   2> 16035 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 16035 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@15e1180b lockFactory=org.apache.lucene.store.NativeFSLockFactory@2bde6713; maxCacheMB=0.0859375 maxMergeSizeMB=0.4384765625))) fullCopy=false
[junit4:junit4]   2> 16038 T307 C22 P43352 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 16040 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index
[junit4:junit4]   2> 16040 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 16041 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 16042 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 16042 T333 C21 P43359 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 16042 T333 C21 P43359 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 16043 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 16045 T333 C21 P43359 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4036a060 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c750751),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4036a060 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c750751),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 16045 T333 C21 P43359 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 16046 T333 C21 P43359 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 16046 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2
[junit4:junit4]   2> 16046 T333 C21 P43359 oass.SolrIndexSearcher.<init> Opening Searcher@d476a5c main
[junit4:junit4]   2> 16048 T332 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d476a5c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 16048 T332 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index
[junit4:junit4]   2> 16049 T333 C21 P43359 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@15e1180b lockFactory=org.apache.lucene.store.NativeFSLockFactory@2bde6713; maxCacheMB=0.0859375 maxMergeSizeMB=0.4384765625)))
[junit4:junit4]   2> 16049 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index.20130302025407488
[junit4:junit4]   2> 16049 T333 C21 P43359 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty2/index
[junit4:junit4]   2> 16050 T333 C21 P43359 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 16050 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 16050 T333 C21 P43359 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 16051 T333 C21 P43359 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16053 T333 C21 P43359 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 16914 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16915 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "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:43364_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43364"}
[junit4:junit4]   2> 16916 T295 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 16916 T295 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 16921 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43359_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43359"}
[junit4:junit4]   2> 16950 T294 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> 16950 T330 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> 16950 T301 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> 16950 T347 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> 16950 T314 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> 17435 T348 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 17435 T348 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43364 collection:collection1 shard:shard1
[junit4:junit4]   2> 17441 T348 oasc.ZkController.register We are http://127.0.0.1:43364/collection1/ and leader is http://127.0.0.1:43352/collection1/
[junit4:junit4]   2> 17442 T348 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43364
[junit4:junit4]   2> 17442 T348 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 17442 T348 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C23 name=collection1 org.apache.solr.core.SolrCore@798212d url=http://127.0.0.1:43364/collection1 node=127.0.0.1:43364_ C23_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43364_, base_url=http://127.0.0.1:43364}
[junit4:junit4]   2> 17443 T352 C23 P43364 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 17443 T348 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17444 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 17444 T352 C23 P43364 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 17444 T352 C23 P43364 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 17445 T272 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 17446 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 17447 T352 C23 P43364 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 17446 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 17652 T272 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 17655 T272 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43373
[junit4:junit4]   2> 17656 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 17656 T272 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 17657 T272 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/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913
[junit4:junit4]   2> 17658 T272 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/solr.xml
[junit4:junit4]   2> 17658 T272 oasc.CoreContainer.<init> New CoreContainer 1377826941
[junit4:junit4]   2> 17659 T272 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/'
[junit4:junit4]   2> 17660 T272 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/'
[junit4:junit4]   2> 17725 T272 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 17726 T272 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 17727 T272 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 17727 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 17728 T272 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 17728 T272 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 17729 T272 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 17729 T272 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 17730 T272 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 17731 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 17753 T272 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 17773 T272 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43327/solr
[junit4:junit4]   2> 17774 T272 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 17775 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@29ad31a6
[junit4:junit4]   2> 17776 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 17776 T363 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 17778 T363 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 17778 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43374
[junit4:junit4]   2> 17778 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43374
[junit4:junit4]   2> 17784 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e000b with negotiated timeout 20000 for client /140.211.11.196:43374
[junit4:junit4]   2> 17784 T363 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e000b, negotiated timeout = 20000
[junit4:junit4]   2> 17785 T364 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@29ad31a6 name:ZooKeeperConnection Watcher:127.0.0.1:43327 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 17785 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 17787 T277 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d293c026e000b
[junit4:junit4]   2> 17800 T364 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 17800 T274 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43374 which had sessionid 0x13d293c026e000b
[junit4:junit4]   2> 17800 T272 oaz.ZooKeeper.close Session: 0x13d293c026e000b closed
[junit4:junit4]   2> 17801 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 17813 T272 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43327/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@29db9390
[junit4:junit4]   2> 17814 T272 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 17814 T365 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43327. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 17815 T365 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43327, initiating session
[junit4:junit4]   2> 17816 T274 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43375
[junit4:junit4]   2> 17816 T274 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43375
[junit4:junit4]   2> 17818 T276 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d293c026e000c with negotiated timeout 20000 for client /140.211.11.196:43375
[junit4:junit4]   2> 17818 T365 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43327, sessionid = 0x13d293c026e000c, negotiated timeout = 20000
[junit4:junit4]   2> 17818 T366 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@29db9390 name:ZooKeeperConnection Watcher:127.0.0.1:43327/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 17819 T272 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 17820 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e000c type:create cxid:0x1 zxid:0x97 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 17822 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e000c type:create cxid:0x2 zxid:0x98 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 17837 T272 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 18466 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18468 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43364_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43364"}
[junit4:junit4]   2> 18531 T294 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> 18531 T347 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> 18531 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> 18531 T330 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> 18531 T301 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> 18531 T314 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> 18841 T272 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43373_
[junit4:junit4]   2> 18843 T277 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d293c026e000c type:delete cxid:0xb zxid:0x9d txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43373_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43373_
[junit4:junit4]   2> 18845 T272 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43373_
[junit4:junit4]   2> 18860 T294 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> 18860 T330 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> 18860 T301 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> 18860 T366 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18860 T347 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18860 T314 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> 18861 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> 18861 T347 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> 18862 T294 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18866 T301 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18867 T330 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18867 T314 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 18872 T367 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/collection1
[junit4:junit4]   2> 18873 T367 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 18874 T367 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 18874 T367 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 18875 T367 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/collection1/'
[junit4:junit4]   2> 18877 T367 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 18877 T367 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/collection1/lib/README' to classloader
[junit4:junit4]   2> 18927 T367 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 19007 T367 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19108 T367 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19117 T367 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 19734 T367 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19747 T367 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19751 T367 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19773 T367 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19779 T367 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19784 T367 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19786 T367 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19786 T367 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19786 T367 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19788 T367 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19788 T367 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19788 T367 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362196448913/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/
[junit4:junit4]   2> 19789 T367 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@27d0e91
[junit4:junit4]   2> 19789 T367 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19790 T367 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4 forceNew:false
[junit4:junit4]   2> 19791 T367 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 19791 T367 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index/
[junit4:junit4]   2> 19792 T367 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19792 T367 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index forceNew:false
[junit4:junit4]   2> 19795 T367 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@aa8d715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@66a22ed7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19796 T367 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19797 T367 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index
[junit4:junit4]   2> 19800 T367 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19800 T367 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19801 T367 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19802 T367 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19803 T367 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19803 T367 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19804 T367 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19805 T367 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19805 T367 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19818 T367 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19825 T367 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 19825 T367 oass.SolrIndexSearcher.<init> Opening Searcher@6fb9fb27 main
[junit4:junit4]   2> 19826 T367 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/tlog
[junit4:junit4]   2> 19827 T367 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19828 T367 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19834 T368 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6fb9fb27 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19837 T367 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 19837 T367 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 20045 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20046 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "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:43373_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43373"}
[junit4:junit4]   2> 20046 T295 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 20046 T295 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20058 T294 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> 20058 T301 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> 20058 T347 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> 20058 T314 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> 20058 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> 20058 T330 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> 20841 T367 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 20841 T367 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43373 collection:collection1 shard:shard1
[junit4:junit4]   2> 20846 T367 oasc.ZkController.register We are http://127.0.0.1:43373/collection1/ and leader is http://127.0.0.1:43352/collection1/
[junit4:junit4]   2> 20847 T367 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43373
[junit4:junit4]   2> 20847 T367 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 20847 T367 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C24 name=collection1 org.apache.solr.core.SolrCore@23e0520a url=http://127.0.0.1:43373/collection1 node=127.0.0.1:43373_ C24_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43373_, base_url=http://127.0.0.1:43373}
[junit4:junit4]   2> 20848 T369 C24 P43373 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 20848 T367 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20849 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 20850 T369 C24 P43373 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 20850 T369 C24 P43373 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 20851 T272 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 20851 T272 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 20852 T369 C24 P43373 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 20852 T272 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 20875 T272 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20877 T272 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 20878 T272 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 20879 T272 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C23_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43364_, base_url=http://127.0.0.1:43364}
[junit4:junit4]   2> 21464 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43352/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 21464 T352 C23 P43364 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43364 START replicas=[http://127.0.0.1:43352/collection1/] nUpdates=100
[junit4:junit4]   2> 21465 T352 C23 P43364 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 21466 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 21466 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 21466 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 21466 T352 C23 P43364 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 21467 T352 C23 P43364 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43352/collection1/. core=collection1
[junit4:junit4]   2> 21467 T352 C23 P43364 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 21469 T305 C22 P43352 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 21480 T310 C22 P43352 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 21481 T310 C22 P43352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 21482 T310 C22 P43352 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 21482 T310 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 21483 T310 C22 P43352 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 21483 T310 C22 P43352 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4]   2> 21484 T352 C23 P43364 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 21485 T352 C23 P43364 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 21487 T307 C22 P43352 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 21488 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4]   2> 21489 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 21489 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 21491 T307 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 21492 T307 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index
[junit4:junit4]   2> 21492 T307 C22 P43352 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1 
[junit4:junit4]   2> 21493 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 21495 T352 C23 P43364 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index.20130302025412948 forceNew:false
[junit4:junit4]   2> 21496 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 21496 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@ca9e09c lockFactory=org.apache.lucene.store.NativeFSLockFactory@36810cca; maxCacheMB=0.0859375 maxMergeSizeMB=0.4384765625))) fullCopy=false
[junit4:junit4]   2> 21499 T307 C22 P43352 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
[junit4:junit4]   2> 21501 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index
[junit4:junit4]   2> 21501 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 21502 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 21503 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 21503 T352 C23 P43364 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 21504 T352 C23 P43364 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 21504 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 21506 T352 C23 P43364 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7eff69f0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bc795ae),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7eff69f0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bc795ae),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 21507 T352 C23 P43364 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 21507 T352 C23 P43364 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 21507 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3
[junit4:junit4]   2> 21508 T352 C23 P43364 oass.SolrIndexSearcher.<init> Opening Searcher@102ae0f0 main
[junit4:junit4]   2> 21509 T349 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@102ae0f0 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4]   2> 21510 T349 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index
[junit4:junit4]   2> 21510 T352 C23 P43364 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@ca9e09c lockFactory=org.apache.lucene.store.NativeFSLockFactory@36810cca; maxCacheMB=0.0859375 maxMergeSizeMB=0.4384765625)))
[junit4:junit4]   2> 21511 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index.20130302025412948
[junit4:junit4]   2> 21511 T352 C23 P43364 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty3/index
[junit4:junit4]   2> 21511 T352 C23 P43364 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 21512 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 21512 T352 C23 P43364 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 21512 T352 C23 P43364 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 21518 T352 C23 P43364 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 21565 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21566 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43373_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43373"}
[junit4:junit4]   2> 21592 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43364_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43364"}
[junit4:junit4]   2> 21612 T294 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> 21612 T347 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> 21612 T314 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> 21612 T330 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> 21612 T301 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> 21612 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> 21881 T272 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22884 T272 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C24_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43373_, base_url=http://127.0.0.1:43373}
[junit4:junit4]   2> 23879 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43352/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 23879 T369 C24 P43373 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43373 START replicas=[http://127.0.0.1:43352/collection1/] nUpdates=100
[junit4:junit4]   2> 23880 T369 C24 P43373 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 23880 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 23881 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 23881 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 23881 T369 C24 P43373 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 23881 T369 C24 P43373 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43352/collection1/. core=collection1
[junit4:junit4]   2> 23882 T369 C24 P43373 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23884 T305 C22 P43352 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 23887 T272 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23895 T304 C22 P43352 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 23896 T304 C22 P43352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 23896 T304 C22 P43352 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 23897 T304 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 23898 T304 C22 P43352 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 23898 T304 C22 P43352 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4]   2> 23899 T369 C24 P43373 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23900 T369 C24 P43373 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 23902 T307 C22 P43352 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 23903 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4]   2> 23904 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 23904 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 23906 T307 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 23907 T307 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index
[junit4:junit4]   2> 23907 T307 C22 P43352 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1 
[junit4:junit4]   2> 23908 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 23912 T369 C24 P43373 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index.20130302025415363 forceNew:false
[junit4:junit4]   2> 23913 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 23914 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7fe32705 lockFactory=org.apache.lucene.store.NativeFSLockFactory@144973dd; maxCacheMB=0.0859375 maxMergeSizeMB=0.4384765625))) fullCopy=false
[junit4:junit4]   2> 23917 T307 C22 P43352 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
[junit4:junit4]   2> 23919 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index
[junit4:junit4]   2> 23919 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 23920 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 23921 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 23921 T369 C24 P43373 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 23921 T369 C24 P43373 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 23922 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 23924 T369 C24 P43373 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@aa8d715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@66a22ed7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@aa8d715 lockFactory=org.apache.lucene.store.NativeFSLockFactory@66a22ed7),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 23924 T369 C24 P43373 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 23925 T369 C24 P43373 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 23925 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4
[junit4:junit4]   2> 23926 T369 C24 P43373 oass.SolrIndexSearcher.<init> Opening Searcher@11fb9657 main
[junit4:junit4]   2> 23927 T368 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@11fb9657 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4]   2> 23928 T368 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index
[junit4:junit4]   2> 23928 T369 C24 P43373 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7fe32705 lockFactory=org.apache.lucene.store.NativeFSLockFactory@144973dd; maxCacheMB=0.0859375 maxMergeSizeMB=0.4384765625)))
[junit4:junit4]   2> 23929 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index.20130302025415363
[junit4:junit4]   2> 23929 T369 C24 P43373 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty4/index
[junit4:junit4]   2> 23929 T369 C24 P43373 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 23930 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 23930 T369 C24 P43373 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 23930 T369 C24 P43373 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 23932 T369 C24 P43373 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 24631 T295 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24633 T295 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[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:43373_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43373"}
[junit4:junit4]   2> 24663 T294 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> 24663 T314 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> 24663 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> 24663 T347 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> 24663 T330 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> 24663 T301 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> 24891 T272 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24892 T272 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C25 name=collection1 org.apache.solr.core.SolrCore@10b79e44 url=http://127.0.0.1:43330/collection1 node=127.0.0.1:43330_ C25_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:43330_, base_url=http://127.0.0.1:43330, leader=true}
[junit4:junit4]   2> 24904 T284 C25 P43330 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 24906 T284 C25 P43330 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data
[junit4:junit4]   2> 24912 T284 C25 P43330 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@24d4969f lockFactory=org.apache.lucene.store.NativeFSLockFactory@340408e4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 24914 T284 C25 P43330 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 24915 T284 C25 P43330 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@24d4969f lockFactory=org.apache.lucene.store.NativeFSLockFactory@340408e4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@24d4969f lockFactory=org.apache.lucene.store.NativeFSLockFactory@340408e4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 24916 T284 C25 P43330 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 24917 T284 C25 P43330 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data
[junit4:junit4]   2> 24918 T284 C25 P43330 oass.SolrIndexSearcher.<init> Opening Searcher@3c44e885 main
[junit4:junit4]   2> 24919 T284 C25 P43330 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 24920 T298 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3c44e885 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 24921 T298 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/control/data/index
[junit4:junit4]   2> 24922 T284 C25 P43330 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 18
[junit4:junit4]   2> 24954 T306 C22 P43352 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 24956 T306 C22 P43352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@75b2a777 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4415eed8),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4]   2> 24956 T306 C22 P43352 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4]   2> 24957 T306 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1
[junit4:junit4]   2> 24957 T306 C22 P43352 oass.SolrIndexSearcher.<init> Opening Searcher@79e9131a main
[junit4:junit4]   2> 24958 T306 C22 P43352 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index
[junit4:junit4]   2> 24958 T306 C22 P43352 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 24960 T316 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@79e9131a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 24960 T316 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1362196431461/jetty1/index
[junit4:junit4]   2> 24961 T306 C22 P43352 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:43359/collection1/, StdNode: http://127.0.0.1:43364/collection1/, StdNode: http://127.0.0.1:43373/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2>  C24_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43373_, base_url=http://127.0.0.1:43373}
[junit4:junit4]   2> 24972 T356 C24 P43373 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2>  C23_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43364_, base_url=http://127.0.0.1:43364}
[junit4:junit4]   2> 24972 T337 C23 P43364 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2>  C21_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=ac

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

achingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-1362197437089/jetty3/index.20130301221057571
[junit4:junit4]   2> 86904 T3342 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-1362197437089/jetty3/index.20130301221057571
[junit4:junit4]   2> 86904 T3342 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-1362197437089/jetty3
[junit4:junit4]   2> 86905 T3342 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-1362197437089/jetty3
[junit4:junit4]   2> 86905 T3342 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 86905 T3342 oasc.LeaderElector$1.process WARNING  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/election/89272971237392394-127.0.0.1:46008__collection1-n_0000000001
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4]   2> 	at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:153)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:150)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:150)
[junit4:junit4]   2> 	at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4]   2> 	at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:243)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4]   2> 
[junit4:junit4]   2> 86906 T3342 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> 86906 T3342 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 86906 T3342 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 86907 T3342 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> 86907 T3342 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 86907 T3342 oasc.LeaderElector$1.process WARNING  org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4]   2> 	at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4]   2> 	at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:236)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:233)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4]   2> 	at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:233)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4]   2> 	at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4]   2> 	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4]   2> 
[junit4:junit4]   2> 86908 T3342 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=SimpleText, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=hr, timezone=America/Mexico_City
[junit4:junit4]   2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_09 (64-bit)/cpus=16,threads=3,free=292495608,total=530579456
[junit4:junit4]   2> NOTE: All tests run in this JVM: [AnalysisAfterCoreReloadTest, SpatialFilterTest, TestArbitraryIndexDir, SimpleFacetsTest, SynonymTokenizerTest, TestCoreContainer, RAMDirectoryFactoryTest, SuggesterFSTTest, SolrRequestParserTest, DisMaxRequestHandlerTest, SpellPossibilityIteratorTest, FileBasedSpellCheckerTest, TestSolr4Spatial, OutputWriterTest, TestAtomicUpdateErrorCases, MBeansHandlerTest, CurrencyFieldXmlFileTest, TestCharFilters, TestSolrCoreProperties, SampleTest, TestUtils, WordBreakSolrSpellCheckerTest, StatelessScriptUpdateProcessorFactoryTest, TestUpdate, TestIndexSearcher, TestDefaultSimilarityFactory, TestQuerySenderListener, TestBadConfig, DistributedSpellCheckComponentTest, CollectionsAPIDistributedZkTest, TestBinaryResponseWriter, TestIndexingPerformance, TestRangeQuery, TestStressVersions, TestSearchPerf, TestSurroundQueryParser, TestRandomFaceting, DirectSolrConnectionTest, DebugComponentTest, TestDocumentBuilder, MinimalSchemaTest, SpellCheckCollatorTest, TestPseudoReturnFields, TestZkChroot, TestElisionMultitermQuery, IndexBasedSpellCheckerTest, ReturnFieldsTest, TestJoin, XsltUpdateRequestHandlerTest, ZkControllerTest, SOLR749Test, SliceStateUpdateTest, DateMathParserTest, TestOmitPositions, TestConfig, SpellCheckComponentTest, TestLMDirichletSimilarityFactory, LeaderElectionIntegrationTest, SliceStateTest, DefaultValueUpdateProcessorTest, ShardRoutingTest, TestSolrXMLSerializer, BasicDistributedZkTest, TestReplicationHandler, TestRealTimeGet, TestExtendedDismaxParser, AutoCommitTest, BasicZkTest, TestFaceting, DistributedTermsComponentTest, StatsComponentTest, TestRecovery, SolrCoreTest, DirectUpdateHandlerTest, TestMultiCoreConfBootstrap, TestGroupingSearch, PeerSyncTest, QueryElevationComponentTest, SortByFunctionTest, SignatureUpdateProcessorFactoryTest, HighlighterTest, CoreAdminHandlerTest, TestRemoteStreaming, CacheHeaderTest, TestWordDelimiterFilterFactory, TestCSVLoader, MoreLikeThisHandlerTest, DocumentBuilderTest, BinaryUpdateRequestHandlerTest, QueryParsingTest, DistanceFunctionTest, StandardRequestHandlerTest, TestPHPSerializedResponseWriter, XmlUpdateRequestHandlerTest, PingRequestHandlerTest, SuggesterWFSTTest, JsonLoaderTest, DirectUpdateHandlerOptimizeTest, IndexSchemaRuntimeFieldTest, SolrPluginUtilsTest, JSONWriterTest, SearchHandlerTest, CopyFieldTest, TestQueryUtils, SuggesterTSTTest, UniqFieldsUpdateProcessorFactoryTest, SuggesterTest, CSVRequestHandlerTest, NotRequiredUniqueKeyTest, TestFoldingMultitermQuery, SolrCoreCheckLockOnStartupTest, TestPropInject, NoCacheHeaderTest, BadComponentTest, TestBinaryField, TestSolrDeletionPolicy2, TestMergePolicyConfig, SolrIndexConfigTest, IndexReaderFactoryTest, TestNumberUtils, MultiTermTest, TestPluginEnable, TestLMJelinekMercerSimilarityFactory, TestCodecSupport, TestFastLRUCache, PluginInfoTest, PrimUtilsTest, OpenExchangeRatesOrgProviderTest, TestSystemIdResolver, TestSuggestSpellingConverter, ChaosMonkeyNothingIsSafeTest, ZkNodePropsTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J0 in 87.20s, 1 test, 1 error <<< FAILURES!

[...truncated 12 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:381: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:361: 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:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:449: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1207: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:870: There were test failures: 260 suites, 1090 tests, 2 suite-level errors, 1 error, 1 failure, 23 ignored (4 assumptions)

Total time: 66 minutes 11 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