You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/03/13 15:35:21 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.8.0-ea-b79) - Build #
4661 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4661/
Java: 32bit/jdk1.8.0-ea-b79 -client -XX:+UseG1GC -XX:MarkStackSize=256K
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=3064, name=coreLoadExecutor-2176-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=3064, name=coreLoadExecutor-2176-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1569)
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:34)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
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:744)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:872)
at org.apache.solr.core.CoreContainer.create(CoreContainer.java:955)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:579)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
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(org.apache.lucene.store.RAMDirectory@1f80e9f lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f11ac)
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=3066, 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=3066, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1569)
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:34)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
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(org.apache.lucene.store.RAMDirectory@13e3506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f10a73)
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.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:44152/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:44152/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([2CC26AE7A4753691:AD24E4FFD32A56AD]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:487)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([2CC26AE7A4753691:AD24E4FFD32A56AD]:0)
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertTrue(Assert.java:54)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:196)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:487)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9302 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T854 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 3 T854 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1363184358705
[junit4:junit4] 2> 4 T854 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 5 T855 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 5 T855 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 5 T855 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 5 T855 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 6 T855 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 6 T855 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1363184358705/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 105 T854 oasc.ZkTestServer.run start zk server on port:54694
[junit4:junit4] 2> 105 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@15c6019
[junit4:junit4] 2> 106 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 106 T860 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 107 T860 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 107 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60433
[junit4:junit4] 2> 107 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60433
[junit4:junit4] 2> 107 T858 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 198 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340000 with negotiated timeout 10000 for client /127.0.0.1:60433
[junit4:junit4] 2> 198 T860 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340000, negotiated timeout = 10000
[junit4:junit4] 2> 199 T861 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15c6019 name:ZooKeeperConnection Watcher:127.0.0.1:54694 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 199 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 200 T854 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 203 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e95340000
[junit4:junit4] 2> 203 T861 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 203 T854 oaz.ZooKeeper.close Session: 0x13d641e95340000 closed
[junit4:junit4] 2> 204 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60433 which had sessionid 0x13d641e95340000
[junit4:junit4] 2> 204 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@19b9e42
[junit4:junit4] 2> 205 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 205 T862 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 205 T862 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 205 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60434
[junit4:junit4] 2> 206 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60434
[junit4:junit4] 2> 206 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340001 with negotiated timeout 10000 for client /127.0.0.1:60434
[junit4:junit4] 2> 206 T862 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340001, negotiated timeout = 10000
[junit4:junit4] 2> 207 T863 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19b9e42 name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 207 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 207 T854 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 210 T854 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 218 T854 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 220 T854 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 221 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 222 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 225 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 225 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 228 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 228 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 230 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 231 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 232 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 233 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 235 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 235 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 239 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 239 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 243 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 243 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 246 T854 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 246 T854 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 248 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e95340001
[junit4:junit4] 2> 248 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60434 which had sessionid 0x13d641e95340001
[junit4:junit4] 2> 248 T854 oaz.ZooKeeper.close Session: 0x13d641e95340001 closed
[junit4:junit4] 2> 249 T863 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 305 T854 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 320 T854 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50458
[junit4:junit4] 2> 320 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 321 T854 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 321 T854 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950
[junit4:junit4] 2> 321 T854 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/solr.xml
[junit4:junit4] 2> 322 T854 oasc.CoreContainer.<init> New CoreContainer 7743645
[junit4:junit4] 2> 322 T854 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/'
[junit4:junit4] 2> 322 T854 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/'
[junit4:junit4] 2> 341 T854 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 341 T854 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 342 T854 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 342 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 342 T854 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 343 T854 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 343 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 343 T854 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 344 T854 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 344 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 351 T854 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 363 T854 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54694/solr
[junit4:junit4] 2> 364 T854 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 364 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@9ec35
[junit4:junit4] 2> 365 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 365 T873 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 366 T873 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 366 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60435
[junit4:junit4] 2> 366 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60435
[junit4:junit4] 2> 367 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340002 with negotiated timeout 20000 for client /127.0.0.1:60435
[junit4:junit4] 2> 367 T873 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340002, negotiated timeout = 20000
[junit4:junit4] 2> 367 T874 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9ec35 name:ZooKeeperConnection Watcher:127.0.0.1:54694 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 368 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 369 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e95340002
[junit4:junit4] 2> 369 T874 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 369 T854 oaz.ZooKeeper.close Session: 0x13d641e95340002 closed
[junit4:junit4] 2> 369 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60435 which had sessionid 0x13d641e95340002
[junit4:junit4] 2> 370 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 373 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@16fe0f6
[junit4:junit4] 2> 373 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 374 T875 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 374 T875 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 374 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60436
[junit4:junit4] 2> 374 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60436
[junit4:junit4] 2> 375 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340003 with negotiated timeout 20000 for client /127.0.0.1:60436
[junit4:junit4] 2> 375 T875 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340003, negotiated timeout = 20000
[junit4:junit4] 2> 376 T876 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16fe0f6 name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 376 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 377 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 378 T854 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 379 T854 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50458_
[junit4:junit4] 2> 380 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:50458_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:50458_
[junit4:junit4] 2> 380 T854 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50458_
[junit4:junit4] 2> 382 T854 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 385 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 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> 385 T854 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 388 T854 oasc.Overseer.start Overseer (id=89337650132287491-127.0.0.1:50458_-n_0000000000) starting
[junit4:junit4] 2> 389 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 389 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 390 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 390 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 391 T878 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 392 T854 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 393 T854 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 395 T854 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 396 T877 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 399 T879 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/collection1
[junit4:junit4] 2> 399 T879 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 400 T879 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 400 T879 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 401 T879 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/collection1/'
[junit4:junit4] 2> 401 T879 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/collection1/lib/README' to classloader
[junit4:junit4] 2> 402 T879 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 429 T879 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 468 T879 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 469 T879 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 473 T879 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 895 T879 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 901 T879 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 904 T879 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 913 T879 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 917 T879 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 920 T879 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 921 T879 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 921 T879 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 921 T879 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 922 T879 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 922 T879 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 922 T879 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 922 T879 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363184358950/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/control/data/
[junit4:junit4] 2> 923 T879 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bb7b67
[junit4:junit4] 2> 923 T879 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 923 T879 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/control/data forceNew: false
[junit4:junit4] 2> 924 T879 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363184358705/control/data/index/
[junit4:junit4] 2> 924 T879 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363184358705/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 924 T879 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/control/data/index forceNew: false
[junit4:junit4] 2> 925 T879 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a74403 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fcde68),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 925 T879 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 927 T879 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 927 T879 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 928 T879 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 928 T879 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 929 T879 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 929 T879 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 929 T879 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 929 T879 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 930 T879 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 932 T879 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 935 T879 oass.SolrIndexSearcher.<init> Opening Searcher@17047d4 main
[junit4:junit4] 2> 935 T879 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/control/data/tlog
[junit4:junit4] 2> 936 T879 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 936 T879 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 940 T880 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17047d4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 941 T879 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 941 T879 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 942 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 1899 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1900 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50458",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:50458_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 1900 T877 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1900 T877 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 1901 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 1904 T876 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> 1944 T879 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1945 T879 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50458 collection:control_collection shard:shard1
[junit4:junit4] 2> 1946 T879 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1952 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:delete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 1953 T879 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1953 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 1955 T879 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1955 T879 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1955 T879 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50458/collection1/
[junit4:junit4] 2> 1956 T879 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1956 T879 oasc.SyncStrategy.syncToMe http://127.0.0.1:50458/collection1/ has no replicas
[junit4:junit4] 2> 1956 T879 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50458/collection1/
[junit4:junit4] 2> 1957 T879 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1960 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3407 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3414 T876 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> 3466 T879 oasc.ZkController.register We are http://127.0.0.1:50458/collection1/ and leader is http://127.0.0.1:50458/collection1/
[junit4:junit4] 2> 3466 T879 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50458
[junit4:junit4] 2> 3466 T879 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3466 T879 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3466 T879 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3468 T879 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3469 T854 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3469 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3470 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3474 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3475 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1ad7a65
[junit4:junit4] 2> 3475 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3476 T882 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3476 T882 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 3476 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60441
[junit4:junit4] 2> 3477 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60441
[junit4:junit4] 2> 3478 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340004 with negotiated timeout 10000 for client /127.0.0.1:60441
[junit4:junit4] 2> 3478 T882 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340004, negotiated timeout = 10000
[junit4:junit4] 2> 3479 T883 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ad7a65 name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3479 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3480 T854 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3481 T854 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3539 T854 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3542 T854 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39830
[junit4:junit4] 2> 3543 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3544 T854 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3544 T854 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183
[junit4:junit4] 2> 3544 T854 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/solr.xml
[junit4:junit4] 2> 3545 T854 oasc.CoreContainer.<init> New CoreContainer 23867151
[junit4:junit4] 2> 3545 T854 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/'
[junit4:junit4] 2> 3545 T854 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/'
[junit4:junit4] 2> 3564 T854 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3564 T854 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3565 T854 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3565 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3565 T854 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3566 T854 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3566 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3566 T854 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3567 T854 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3567 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3574 T854 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3587 T854 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54694/solr
[junit4:junit4] 2> 3587 T854 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3588 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1a5aa7b
[junit4:junit4] 2> 3589 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3589 T893 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3589 T893 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 3590 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60442
[junit4:junit4] 2> 3590 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60442
[junit4:junit4] 2> 3591 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340005 with negotiated timeout 20000 for client /127.0.0.1:60442
[junit4:junit4] 2> 3591 T893 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340005, negotiated timeout = 20000
[junit4:junit4] 2> 3591 T894 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a5aa7b name:ZooKeeperConnection Watcher:127.0.0.1:54694 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3591 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3592 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e95340005
[junit4:junit4] 2> 3593 T894 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3592 T854 oaz.ZooKeeper.close Session: 0x13d641e95340005 closed
[junit4:junit4] 2> 3593 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60442 which had sessionid 0x13d641e95340005
[junit4:junit4] 2> 3593 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3596 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@173323b
[junit4:junit4] 2> 3597 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3597 T895 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3597 T895 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 3597 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60443
[junit4:junit4] 2> 3598 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60443
[junit4:junit4] 2> 3598 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340006 with negotiated timeout 20000 for client /127.0.0.1:60443
[junit4:junit4] 2> 3598 T895 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340006, negotiated timeout = 20000
[junit4:junit4] 2> 3599 T896 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@173323b name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3599 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3600 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3600 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3602 T854 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4604 T854 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39830_
[junit4:junit4] 2> 4605 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:39830_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:39830_
[junit4:junit4] 2> 4606 T854 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39830_
[junit4:junit4] 2> 4609 T876 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4609 T876 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> 4609 T896 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4610 T883 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4614 T897 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/collection1
[junit4:junit4] 2> 4614 T897 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4615 T897 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4615 T897 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4616 T897 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/collection1/'
[junit4:junit4] 2> 4616 T897 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/collection1/lib/README' to classloader
[junit4:junit4] 2> 4616 T897 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4644 T897 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 4681 T897 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4682 T897 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4686 T897 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 4917 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 4918 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50458",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:50458_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 4921 T883 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> 4921 T896 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> 4922 T876 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> 5097 T897 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5103 T897 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5106 T897 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5117 T897 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5121 T897 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5125 T897 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5126 T897 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5127 T897 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5127 T897 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5128 T897 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5128 T897 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5128 T897 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5129 T897 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363184362183/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty1/
[junit4:junit4] 2> 5129 T897 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bb7b67
[junit4:junit4] 2> 5129 T897 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5130 T897 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty1 forceNew: false
[junit4:junit4] 2> 5130 T897 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty1/index/
[junit4:junit4] 2> 5130 T897 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5131 T897 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty1/index forceNew: false
[junit4:junit4] 2> 5132 T897 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5132 T897 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5134 T897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5135 T897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5135 T897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5135 T897 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5136 T897 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5136 T897 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5136 T897 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5137 T897 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5137 T897 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5140 T897 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5142 T897 oass.SolrIndexSearcher.<init> Opening Searcher@374b1c main
[junit4:junit4] 2> 5143 T897 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty1/tlog
[junit4:junit4] 2> 5143 T897 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5143 T897 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5147 T898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@374b1c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5149 T897 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5149 T897 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6425 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6426 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39830",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:39830_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 6426 T877 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6426 T877 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6430 T883 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> 6430 T896 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> 6430 T876 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> 7150 T897 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7150 T897 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39830 collection:collection1 shard:shard1
[junit4:junit4] 2> 7151 T897 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7156 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340006 type:delete cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7157 T897 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7157 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7158 T897 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7158 T897 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7158 T897 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39830/collection1/
[junit4:junit4] 2> 7159 T897 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7159 T897 oasc.SyncStrategy.syncToMe http://127.0.0.1:39830/collection1/ has no replicas
[junit4:junit4] 2> 7159 T897 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39830/collection1/
[junit4:junit4] 2> 7159 T897 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7162 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7944 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7951 T876 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> 7951 T883 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> 7951 T896 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> 7966 T897 oasc.ZkController.register We are http://127.0.0.1:39830/collection1/ and leader is http://127.0.0.1:39830/collection1/
[junit4:junit4] 2> 7966 T897 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39830
[junit4:junit4] 2> 7966 T897 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 7967 T897 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 7967 T897 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 7969 T897 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7970 T854 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 7970 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 7971 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8034 T854 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8036 T854 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40089
[junit4:junit4] 2> 8037 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8037 T854 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8038 T854 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675
[junit4:junit4] 2> 8038 T854 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/solr.xml
[junit4:junit4] 2> 8039 T854 oasc.CoreContainer.<init> New CoreContainer 2500714
[junit4:junit4] 2> 8039 T854 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/'
[junit4:junit4] 2> 8039 T854 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/'
[junit4:junit4] 2> 8058 T854 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8058 T854 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8059 T854 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8059 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8059 T854 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8060 T854 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8060 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8060 T854 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8061 T854 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8061 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8068 T854 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8080 T854 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54694/solr
[junit4:junit4] 2> 8081 T854 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8081 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@896a7d
[junit4:junit4] 2> 8082 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8082 T909 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8082 T909 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 8083 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60449
[junit4:junit4] 2> 8083 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60449
[junit4:junit4] 2> 8084 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340007 with negotiated timeout 20000 for client /127.0.0.1:60449
[junit4:junit4] 2> 8084 T909 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340007, negotiated timeout = 20000
[junit4:junit4] 2> 8084 T910 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@896a7d name:ZooKeeperConnection Watcher:127.0.0.1:54694 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8084 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8085 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e95340007
[junit4:junit4] 2> 8085 T910 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8085 T854 oaz.ZooKeeper.close Session: 0x13d641e95340007 closed
[junit4:junit4] 2> 8085 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60449 which had sessionid 0x13d641e95340007
[junit4:junit4] 2> 8086 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8089 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@8d3840
[junit4:junit4] 2> 8089 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8090 T911 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8090 T911 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 8090 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60450
[junit4:junit4] 2> 8091 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60450
[junit4:junit4] 2> 8091 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340008 with negotiated timeout 20000 for client /127.0.0.1:60450
[junit4:junit4] 2> 8091 T911 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340008, negotiated timeout = 20000
[junit4:junit4] 2> 8092 T912 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8d3840 name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8092 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8093 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8093 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8095 T854 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9097 T854 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40089_
[junit4:junit4] 2> 9098 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e95340008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:40089_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:40089_
[junit4:junit4] 2> 9099 T854 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40089_
[junit4:junit4] 2> 9101 T876 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> 9101 T896 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> 9102 T883 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9103 T883 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> 9103 T912 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9104 T896 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9104 T876 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9108 T913 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/collection1
[junit4:junit4] 2> 9109 T913 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9109 T913 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9109 T913 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9110 T913 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/collection1/'
[junit4:junit4] 2> 9111 T913 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/collection1/lib/README' to classloader
[junit4:junit4] 2> 9111 T913 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9139 T913 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 9176 T913 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9177 T913 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9181 T913 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9455 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9456 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39830",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39830_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 9459 T883 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> 9459 T876 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> 9459 T912 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> 9459 T896 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> 9588 T913 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9594 T913 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9597 T913 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9608 T913 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9611 T913 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9615 T913 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9616 T913 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9616 T913 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9616 T913 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9617 T913 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9617 T913 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9617 T913 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9617 T913 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363184366675/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2/
[junit4:junit4] 2> 9618 T913 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bb7b67
[junit4:junit4] 2> 9618 T913 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9619 T913 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2 forceNew: false
[junit4:junit4] 2> 9619 T913 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2/index/
[junit4:junit4] 2> 9619 T913 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9619 T913 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2/index forceNew: false
[junit4:junit4] 2> 9620 T913 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9621 T913 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9622 T913 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9622 T913 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9623 T913 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9623 T913 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9624 T913 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9624 T913 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9624 T913 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9624 T913 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9625 T913 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9627 T913 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9630 T913 oass.SolrIndexSearcher.<init> Opening Searcher@11ba263 main
[junit4:junit4] 2> 9630 T913 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2/tlog
[junit4:junit4] 2> 9630 T913 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9631 T913 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9636 T914 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@11ba263 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9639 T913 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9640 T913 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 10964 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 10965 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40089",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40089_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 10965 T877 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 10965 T877 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 10969 T912 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> 10969 T896 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> 10970 T876 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> 10970 T883 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> 11641 T913 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11641 T913 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40089 collection:collection1 shard:shard1
[junit4:junit4] 2> 11645 T913 oasc.ZkController.register We are http://127.0.0.1:40089/collection1/ and leader is http://127.0.0.1:39830/collection1/
[junit4:junit4] 2> 11645 T913 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40089
[junit4:junit4] 2> 11645 T913 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11645 T913 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C33 name=collection1 org.apache.solr.core.SolrCore@185a70e url=http://127.0.0.1:40089/collection1 node=127.0.0.1:40089_ C33_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:40089, collection=collection1, node_name=127.0.0.1:40089_, core=collection1}
[junit4:junit4] 2> 11646 T915 C33 P40089 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11646 T913 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11646 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11647 T915 C33 P40089 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11647 T915 C33 P40089 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11647 T854 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11647 T915 C33 P40089 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11647 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11648 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11708 T854 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11714 T854 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35030
[junit4:junit4] 2> 11715 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11715 T854 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11716 T854 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351
[junit4:junit4] 2> 11716 T854 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/solr.xml
[junit4:junit4] 2> 11716 T854 oasc.CoreContainer.<init> New CoreContainer 17811912
[junit4:junit4] 2> 11717 T854 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/'
[junit4:junit4] 2> 11717 T854 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/'
[junit4:junit4] 2> 11736 T854 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 11736 T854 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11737 T854 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11737 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11737 T854 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11738 T854 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11738 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11738 T854 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11739 T854 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11739 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11746 T854 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11758 T854 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54694/solr
[junit4:junit4] 2> 11758 T854 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11759 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@142a0b0
[junit4:junit4] 2> 11760 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11760 T926 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 11760 T926 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 11760 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60455
[junit4:junit4] 2> 11761 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60455
[junit4:junit4] 2> 11761 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e95340009 with negotiated timeout 20000 for client /127.0.0.1:60455
[junit4:junit4] 2> 11761 T926 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e95340009, negotiated timeout = 20000
[junit4:junit4] 2> 11762 T927 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@142a0b0 name:ZooKeeperConnection Watcher:127.0.0.1:54694 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11762 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11763 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e95340009
[junit4:junit4] 2> 11764 T927 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 11764 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60455 which had sessionid 0x13d641e95340009
[junit4:junit4] 2> 11764 T854 oaz.ZooKeeper.close Session: 0x13d641e95340009 closed
[junit4:junit4] 2> 11764 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 11767 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d124a6
[junit4:junit4] 2> 11768 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11768 T928 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 11769 T928 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 11769 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60456
[junit4:junit4] 2> 11769 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60456
[junit4:junit4] 2> 11770 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e9534000a with negotiated timeout 20000 for client /127.0.0.1:60456
[junit4:junit4] 2> 11770 T928 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e9534000a, negotiated timeout = 20000
[junit4:junit4] 2> 11770 T929 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d124a6 name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11770 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11771 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e9534000a type:create cxid:0x1 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11772 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e9534000a type:create cxid:0x2 zxid:0x82 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11773 T854 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12474 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12475 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40089",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40089_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 12478 T912 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> 12478 T883 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> 12478 T896 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> 12478 T876 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> 12478 T929 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> 12652 T889 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {state=recovering&onlyIfLeader=true&coreNodeName=3&version=2&nodeName=127.0.0.1:40089_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin} status=0 QTime=1000
[junit4:junit4] 2> 12775 T854 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35030_
[junit4:junit4] 2> 12776 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e9534000a type:delete cxid:0xd zxid:0x87 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:35030_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:35030_
[junit4:junit4] 2> 12777 T854 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35030_
[junit4:junit4] 2> 12779 T883 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> 12779 T912 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> 12779 T876 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12779 T896 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> 12779 T929 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> 12779 T876 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> 12780 T912 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12781 T883 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12781 T896 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12782 T929 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12785 T930 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/collection1
[junit4:junit4] 2> 12785 T930 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 12786 T930 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 12786 T930 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 12787 T930 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/collection1/'
[junit4:junit4] 2> 12787 T930 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/collection1/lib/README' to classloader
[junit4:junit4] 2> 12788 T930 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 12830 T930 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 12867 T930 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 12868 T930 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 12873 T930 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13287 T930 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13293 T930 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13296 T930 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13306 T930 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13309 T930 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13313 T930 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13315 T930 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 13315 T930 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 13315 T930 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13316 T930 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 13316 T930 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 13316 T930 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 13317 T930 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363184370351/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3/
[junit4:junit4] 2> 13317 T930 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bb7b67
[junit4:junit4] 2> 13317 T930 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 13318 T930 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3 forceNew: false
[junit4:junit4] 2> 13318 T930 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3/index/
[junit4:junit4] 2> 13318 T930 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13318 T930 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3/index forceNew: false
[junit4:junit4] 2> 13319 T930 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13320 T930 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13321 T930 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13321 T930 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13322 T930 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13322 T930 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13323 T930 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13323 T930 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13323 T930 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13324 T930 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13324 T930 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13326 T930 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13329 T930 oass.SolrIndexSearcher.<init> Opening Searcher@5314d2 main
[junit4:junit4] 2> 13330 T930 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3/tlog
[junit4:junit4] 2> 13330 T930 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13330 T930 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13336 T931 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5314d2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13338 T930 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13338 T930 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 13983 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13984 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35030",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:35030_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 13984 T877 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 13984 T877 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 13988 T883 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> 13988 T912 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> 13989 T929 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> 13988 T896 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> 13989 T876 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> 14340 T930 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 14340 T930 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35030 collection:collection1 shard:shard1
[junit4:junit4] 2> 14344 T930 oasc.ZkController.register We are http://127.0.0.1:35030/collection1/ and leader is http://127.0.0.1:39830/collection1/
[junit4:junit4] 2> 14344 T930 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35030
[junit4:junit4] 2> 14344 T930 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 14345 T930 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C34 name=collection1 org.apache.solr.core.SolrCore@1f9395e url=http://127.0.0.1:35030/collection1 node=127.0.0.1:35030_ C34_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:35030, collection=collection1, node_name=127.0.0.1:35030_, core=collection1}
[junit4:junit4] 2> 14345 T932 C34 P35030 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 14345 T930 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14346 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 14346 T932 C34 P35030 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 14346 T932 C34 P35030 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14347 T854 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 14347 T932 C34 P35030 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14347 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 14348 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14409 T854 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 14412 T854 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59635
[junit4:junit4] 2> 14412 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 14412 T854 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 14413 T854 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053
[junit4:junit4] 2> 14413 T854 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/solr.xml
[junit4:junit4] 2> 14414 T854 oasc.CoreContainer.<init> New CoreContainer 20899737
[junit4:junit4] 2> 14414 T854 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/'
[junit4:junit4] 2> 14414 T854 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/'
[junit4:junit4] 2> 14433 T854 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 14433 T854 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 14434 T854 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 14434 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 14434 T854 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 14435 T854 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 14435 T854 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 14435 T854 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 14436 T854 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 14436 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 14443 T854 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 14458 T854 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54694/solr
[junit4:junit4] 2> 14459 T854 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 14459 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@32c75a
[junit4:junit4] 2> 14460 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 14460 T943 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 14461 T943 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 14461 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60461
[junit4:junit4] 2> 14461 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60461
[junit4:junit4] 2> 14462 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e9534000b with negotiated timeout 20000 for client /127.0.0.1:60461
[junit4:junit4] 2> 14462 T943 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e9534000b, negotiated timeout = 20000
[junit4:junit4] 2> 14462 T944 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32c75a name:ZooKeeperConnection Watcher:127.0.0.1:54694 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 14463 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 14464 T859 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d641e9534000b
[junit4:junit4] 2> 14464 T856 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60461 which had sessionid 0x13d641e9534000b
[junit4:junit4] 2> 14464 T944 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 14464 T854 oaz.ZooKeeper.close Session: 0x13d641e9534000b closed
[junit4:junit4] 2> 14465 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 14468 T854 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54694/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@19143c8
[junit4:junit4] 2> 14468 T854 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 14469 T945 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54694. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 14469 T945 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54694, initiating session
[junit4:junit4] 2> 14469 T856 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60462
[junit4:junit4] 2> 14470 T856 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60462
[junit4:junit4] 2> 14470 T858 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d641e9534000c with negotiated timeout 20000 for client /127.0.0.1:60462
[junit4:junit4] 2> 14471 T945 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54694, sessionid = 0x13d641e9534000c, negotiated timeout = 20000
[junit4:junit4] 2> 14471 T946 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19143c8 name:ZooKeeperConnection Watcher:127.0.0.1:54694/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 14471 T854 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 14472 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e9534000c type:create cxid:0x1 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 14473 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e9534000c type:create cxid:0x2 zxid:0x95 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 14474 T854 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> C33_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:40089, collection=collection1, shard=shard1, node_name=127.0.0.1:40089_, core=collection1}
[junit4:junit4] 2> 14653 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39830/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 14653 T915 C33 P40089 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40089 START replicas=[http://127.0.0.1:39830/collection1/] nUpdates=100
[junit4:junit4] 2> 14653 T915 C33 P40089 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 14653 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 14654 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 14654 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 14654 T915 C33 P40089 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 14654 T915 C33 P40089 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39830/collection1/. core=collection1
[junit4:junit4] 2> 14655 T915 C33 P40089 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C35 name=collection1 org.apache.solr.core.SolrCore@18b2680 url=http://127.0.0.1:39830/collection1 node=127.0.0.1:39830_ C35_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:39830, collection=collection1, shard=shard1, node_name=127.0.0.1:39830_, core=collection1, leader=true}
[junit4:junit4] 2> 14659 T890 C35 P39830 REQ /get {qt=/get&distrib=false&version=2&wt=javabin&getVersions=100} status=0 QTime=1
[junit4:junit4] 2> 14662 T892 C35 P39830 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14663 T892 C35 P39830 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 14664 T892 C35 P39830 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 14665 T892 C35 P39830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 14665 T892 C35 P39830 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 14665 T892 C35 P39830 oass.SolrIndexSearcher.<init> Opening Searcher@1a1da23 realtime
[junit4:junit4] 2> 14666 T892 C35 P39830 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 14666 T892 C35 P39830 /update {waitSearcher=true&openSearcher=false&softCommit=false&version=2&commit_end_point=true&commit=true&wt=javabin} {commit=} 0 4
[junit4:junit4] 2> 14667 T915 C33 P40089 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14667 T915 C33 P40089 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 14671 T889 C35 P39830 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14672 T889 C35 P39830 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=4
[junit4:junit4] 2> 14672 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 14672 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 14672 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 14674 T892 C35 P39830 REQ /replication {generation=2&qt=/replication&version=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 14675 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 14676 T915 C33 P40089 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty2/index.20130313081933376 forceNew: false
[junit4:junit4] 2> 14676 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@186281 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d57600) fullCopy=false
[junit4:junit4] 2> 14679 T890 C35 P39830 REQ /replication {generation=2&qt=/replication&checksum=true&file=segments_2&command=filecontent&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 14680 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 14681 T915 C33 P40089 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 14681 T915 C33 P40089 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 14682 T915 C33 P40089 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 14683 T915 C33 P40089 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 14683 T915 C33 P40089 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 14683 T915 C33 P40089 oass.SolrIndexSearcher.<init> Opening Searcher@61485f main
[junit4:junit4] 2> 14684 T914 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@61485f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 14685 T915 C33 P40089 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@186281 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d57600)
[junit4:junit4] 2> 14685 T915 C33 P40089 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 14685 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 14685 T915 C33 P40089 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 14685 T915 C33 P40089 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14686 T915 C33 P40089 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15476 T854 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59635_
[junit4:junit4] 2> 15477 T859 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d641e9534000c type:delete cxid:0xb zxid:0x97 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59635_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59635_
[junit4:junit4] 2> 15478 T854 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59635_
[junit4:junit4] 2> 15479 T876 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> 15479 T896 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> 15479 T912 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> 15480 T929 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> 15481 T946 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15481 T883 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15481 T883 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> 15482 T876 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15483 T929 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15483 T912 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15483 T896 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 15487 T949 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/collection1
[junit4:junit4] 2> 15487 T949 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 15488 T949 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 15488 T949 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 15489 T949 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/collection1/'
[junit4:junit4] 2> 15489 T949 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/collection1/lib/README' to classloader
[junit4:junit4] 2> 15489 T949 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 15492 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15493 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35030",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:35030_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 15495 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40089",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40089_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 15498 T883 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> 15498 T929 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> 15498 T876 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> 15499 T912 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> 15498 T896 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> 15498 T946 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> 15518 T949 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 15556 T949 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 15557 T949 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 15562 T949 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 15981 T949 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 15987 T949 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 15990 T949 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 16000 T949 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 16003 T949 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 16006 T949 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 16007 T949 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 16007 T949 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 16007 T949 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 16008 T949 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 16008 T949 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 16009 T949 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 16009 T949 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363184373053/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4/
[junit4:junit4] 2> 16009 T949 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1bb7b67
[junit4:junit4] 2> 16009 T949 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 16010 T949 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4 forceNew: false
[junit4:junit4] 2> 16010 T949 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4/index/
[junit4:junit4] 2> 16010 T949 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 16010 T949 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4/index forceNew: false
[junit4:junit4] 2> 16012 T949 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@89d030 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4eb5b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 16012 T949 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 16013 T949 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 16013 T949 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 16014 T949 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 16014 T949 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 16015 T949 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 16015 T949 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 16015 T949 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 16016 T949 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 16016 T949 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 16018 T949 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 16021 T949 oass.SolrIndexSearcher.<init> Opening Searcher@1370d48 main
[junit4:junit4] 2> 16021 T949 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4/tlog
[junit4:junit4] 2> 16021 T949 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 16022 T949 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 16026 T950 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1370d48 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 16028 T949 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 16028 T949 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16353 T891 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {state=recovering&onlyIfLeader=true&coreNodeName=4&version=2&nodeName=127.0.0.1:35030_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin} status=0 QTime=2000
[junit4:junit4] 2> 17004 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17005 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59635",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59635_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 17005 T877 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 17005 T877 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 17008 T876 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> 17008 T912 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> 17009 T896 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> 17008 T946 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> 17008 T929 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> 17008 T883 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> 17029 T949 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 17030 T949 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59635 collection:collection1 shard:shard1
[junit4:junit4] 2> 17049 T949 oasc.ZkController.register We are http://127.0.0.1:59635/collection1/ and leader is http://127.0.0.1:39830/collection1/
[junit4:junit4] 2> 17049 T949 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59635
[junit4:junit4] 2> 17049 T949 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 17050 T949 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C36 name=collection1 org.apache.solr.core.SolrCore@a8dac4 url=http://127.0.0.1:59635/collection1 node=127.0.0.1:59635_ C36_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:59635, collection=collection1, node_name=127.0.0.1:59635_, core=collection1}
[junit4:junit4] 2> 17050 T951 C36 P59635 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 17051 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 17051 T949 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17051 T951 C36 P59635 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 17051 T951 C36 P59635 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 17052 T854 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 17052 T854 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 17053 T854 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 17055 T951 C36 P59635 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 17056 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17057 T854 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 17058 T854 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 17058 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18060 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C34_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:35030, collection=collection1, shard=shard1, node_name=127.0.0.1:35030_, core=collection1}
[junit4:junit4] 2> 18354 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39830/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 18355 T932 C34 P35030 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:35030 START replicas=[http://127.0.0.1:39830/collection1/] nUpdates=100
[junit4:junit4] 2> 18355 T932 C34 P35030 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 18355 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 18355 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 18356 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 18356 T932 C34 P35030 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 18356 T932 C34 P35030 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39830/collection1/. core=collection1
[junit4:junit4] 2> 18356 T932 C34 P35030 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18357 T889 C35 P39830 REQ /get {qt=/get&distrib=false&version=2&wt=javabin&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 18360 T890 C35 P39830 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 18361 T890 C35 P39830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18361 T890 C35 P39830 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18361 T890 C35 P39830 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18362 T890 C35 P39830 /update {waitSearcher=true&openSearcher=false&softCommit=false&version=2&commit_end_point=true&commit=true&wt=javabin} {commit=} 0 2
[junit4:junit4] 2> 18362 T932 C34 P35030 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18363 T932 C34 P35030 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 18364 T889 C35 P39830 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 18365 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 18365 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 18365 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 18367 T890 C35 P39830 REQ /replication {generation=3&qt=/replication&version=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 18368 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 18369 T932 C34 P35030 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty3/index.20130313081937069 forceNew: false
[junit4:junit4] 2> 18369 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@19a7d0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@155ecc5) fullCopy=false
[junit4:junit4] 2> 18372 T892 C35 P39830 REQ /replication {generation=3&qt=/replication&checksum=true&file=segments_3&command=filecontent&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 18373 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 18374 T932 C34 P35030 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 18374 T932 C34 P35030 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 18375 T932 C34 P35030 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18375 T932 C34 P35030 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18375 T932 C34 P35030 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 18375 T932 C34 P35030 oass.SolrIndexSearcher.<init> Opening Searcher@f177f9 main
[junit4:junit4] 2> 18376 T931 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f177f9 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 18377 T932 C34 P35030 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@19a7d0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@155ecc5)
[junit4:junit4] 2> 18377 T932 C34 P35030 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 18377 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 18377 T932 C34 P35030 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 18378 T932 C34 P35030 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18379 T932 C34 P35030 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 18513 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18514 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59635",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59635_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 18517 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35030",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:35030_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 18519 T876 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> 18519 T912 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> 18520 T929 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> 18519 T883 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> 18520 T946 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> 18520 T896 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> 19058 T891 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {state=recovering&onlyIfLeader=true&coreNodeName=5&version=2&nodeName=127.0.0.1:59635_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin} status=0 QTime=2000
[junit4:junit4] 2> 19061 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20063 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C36_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:59635, collection=collection1, shard=shard1, node_name=127.0.0.1:59635_, core=collection1}
[junit4:junit4] 2> 21059 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39830/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 21060 T951 C36 P59635 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59635 START replicas=[http://127.0.0.1:39830/collection1/] nUpdates=100
[junit4:junit4] 2> 21060 T951 C36 P59635 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 21060 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 21060 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 21060 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 21061 T951 C36 P59635 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 21061 T951 C36 P59635 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39830/collection1/. core=collection1
[junit4:junit4] 2> 21061 T951 C36 P59635 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21062 T891 C35 P39830 REQ /get {qt=/get&distrib=false&version=2&wt=javabin&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 21064 T892 C35 P39830 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 21065 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21065 T892 C35 P39830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21065 T892 C35 P39830 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21066 T892 C35 P39830 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21066 T892 C35 P39830 /update {waitSearcher=true&openSearcher=false&softCommit=false&version=2&commit_end_point=true&commit=true&wt=javabin} {commit=} 0 2
[junit4:junit4] 2> 21067 T951 C36 P59635 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21067 T951 C36 P59635 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 21069 T891 C35 P39830 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 21069 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 21070 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 21070 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 21071 T892 C35 P39830 REQ /replication {generation=4&qt=/replication&version=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 21072 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 21073 T951 C36 P59635 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363184358705/jetty4/index.20130313081939773 forceNew: false
[junit4:junit4] 2> 21073 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@e16f06 lockFactory=org.apache.lucene.store.NativeFSLockFactory@62424e) fullCopy=false
[junit4:junit4] 2> 21076 T889 C35 P39830 REQ /replication {generation=4&qt=/replication&checksum=true&file=segments_4&command=filecontent&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 21077 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 21078 T951 C36 P59635 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 21078 T951 C36 P59635 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 21079 T951 C36 P59635 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@89d030 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4eb5b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@89d030 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4eb5b),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21079 T951 C36 P59635 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21079 T951 C36 P59635 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 21079 T951 C36 P59635 oass.SolrIndexSearcher.<init> Opening Searcher@1b33039 main
[junit4:junit4] 2> 21080 T950 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b33039 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 21081 T951 C36 P59635 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@e16f06 lockFactory=org.apache.lucene.store.NativeFSLockFactory@62424e)
[junit4:junit4] 2> 21081 T951 C36 P59635 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 21081 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 21081 T951 C36 P59635 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 21081 T951 C36 P59635 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21082 T951 C36 P59635 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 21527 T877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21528 T877 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59635",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59635_",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 21531 T883 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> 21531 T929 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> 21531 T946 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> 21531 T896 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> 21531 T912 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> 21531 T876 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> 22066 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22067 T854 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C37 name=collection1 org.apache.solr.core.SolrCore@bf48da url=http://127.0.0.1:50458/collection1 node=127.0.0.1:50458_ C37_STATE=coll:control_collection core:collection1 props:{state=active, base_url=http://127.0.0.1:50458, collection=control_collection, shard=shard1, node_name=127.0.0.1:50458_, core=collection1, leader=true}
[junit4:junit4] 2> 22074 T869 C37 P50458 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22076 T869 C37 P50458 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a74403 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fcde68),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22077 T869 C37 P50458 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22077 T869 C37 P50458 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a74403 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fcde68),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a74403 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fcde68),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22078 T869 C37 P50458 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22078 T869 C37 P50458 oass.SolrIndexSearcher.<init> Opening Searcher@970ab1 main
[junit4:junit4] 2> 22079 T869 C37 P50458 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22080 T880 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@970ab1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 22080 T869 C37 P50458 /update {waitSearcher=true&softCommit=false&version=2&commit=true&wt=javabin} {commit=} 0 6
[junit4:junit4] 2> 22084 T890 C35 P39830 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22084 T890 C35 P39830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22085 T890 C35 P39830 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22085 T890 C35 P39830 oass.SolrIndexSearcher.<init> Opening Searcher@fab671 main
[junit4:junit4] 2> 22085 T890 C35 P39830 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22086 T898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@fab671 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22086 T890 C35 P39830 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:40089/collection1/, StdNode: http://127.0.0.1:35030/collection1/, StdNode: http://127.0.0.1:59635/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C34_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:35030, collection=collection1, shard=shard1, node_name=127.0.0.1:35030_, core=collection1}
[junit4:junit4] 2> 22093 T923 C34 P35030 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22094 T923 C34 P35030 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 22095 T923 C34 P35030 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 22095 T923 C34 P35030 oass.SolrIndexSearcher.<init> Opening Searcher@1357487 main
[junit4:junit4] 2> 22096 T923 C34 P35030 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> C36_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:59635, collection=collection1, shard=shard1, node_name=127.0.0.1:59635_, core=collection1}
[junit4:junit4] 2> 22096 T940 C36 P59635 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22097 T931 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1357487 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 22097 T940 C36 P59635 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@89d030 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4eb5b),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@89d030 lockFactory=org.apache.lucene.store.NativeFSLockFactory@f4eb5b),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> C33_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:40089, collection=collection1, shard=shard1, node_name=127.0.0.1:40089_, core=collection1}
[junit4:junit4] 2> 22097 T907 C33 P40089 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22097 T923 C34 P35030 /update {waitSearcher=true&expungeDeletes=false&softCommit=false&version=2&commit_end_point=true&commit=true&wt=javabin} {commit=} 0 4
[junit4:junit4] 2> 22097 T940 C36 P59635 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22098 T907 C33 P40089 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 22098 T940 C36 P59635 oass.SolrIndexSearcher.<init> Opening Searcher@1ffdc51 main
[junit4:junit4] 2> 22099 T907 C33 P40089 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 22099 T940 C36 P59635 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22099 T907 C33 P40089 oass.SolrIndexSearcher.<init> Opening Searcher@bc1784 main
[junit4:junit4] 2> 22100 T950 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ffdc51 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 22100 T907 C33 P40089 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22100 T914 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bc1784 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22101 T940 C36 P59635 /update {waitSearcher=true&expungeDeletes=false&softCommit=false&version=2&commit_end_point=true&commit=true&wt=javabin} {commit=} 0 5
[junit4:junit4] 2> 22101 T907 C33 P40089 /update {waitSearcher=true&expungeDeletes=false&softCommit=false&version=2&commit_end_point=true&commit=true&wt=javabin} {commit=} 0 4
[junit4:junit4] 2> 22101 T890 C35 P39830 /update {waitSearcher=true&softCommit=false&version=2&commit=true&wt=javabin} {commit=} 0 17
[junit4:junit4] 2> 22102 T854 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22104 T891 C35 P39830 REQ /select {q=*:*&distrib=false&version=2&tests=checkShardConsistency&rows=0&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22106 T905 C33 P40089 REQ /select {q=*:*&distrib=false&version=2&tests=checkShardConsistency&rows=0&wt=javabin} hits=0 status=0 QTime=1
[junit4:junit4] 2> 22107 T924 C34 P35030 REQ /select {q=*:*&distrib=false&version=2&tests=checkShardConsistency&rows=0&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22108 T942 C36 P59635 REQ /select {q=*:*&distrib=false&version=2&tests=checkShardConsistency&rows=0&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 24112 T869 C37 P50458 oass.SolrIndexSearcher.<init> Opening Searcher@1dd7129 realtime
[junit4:junit4] 2> 24112 T869 C37 P50458 /update {version=2&wt=javabin} {deleteByQuery=*:* (-1429402427391475712)} 0 1
[junit4:junit4] 2> 24118 T923 C34 P35030 /update {_version_=-1429402427395670016&version=2&update.distrib=FROMLEADER&update.from=http://127.0.0.1:39830/collection1/&wt=javabin} {deleteByQuery=*:* (-1429402427395670016)} 0 1
[junit4:junit4] 2> 24118 T940 C36 P59635 /update {_version_=-1429402427395670016&version=2&update.distrib=FROMLEADER&update.from=http://127.0.0.1:39830/collection1/&wt=javabin} {deleteByQuery=*:* (-1429402427395670016)} 0 1
[junit4:junit4] 2> 24118 T905 C33 P40089 /update {_version_=-1429402427395670016&version=2&update.distrib=FROMLEADER&update.from=http://127.0.0.1:39830/collection1/&wt=javabin} {deleteByQuery=*:* (-1429402427395670016)} 0 0
[junit4:junit4] 2> 24119 T890 C35 P39830 /update {version=2&wt=javabin} {deleteByQuery=*:* (-1429402427395670016)} 0 4
[junit4:junit4] 2> 24123 T870 C37 P50458 /update {version=2&wt=javabin} {add=[0 (1429402427403010048)]} 0 1
[junit4:junit4] 2> 24129 T942 C36 P59635 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[0 (1429402427406155776)]} 0 1
[junit4:junit4] 2> 24129 T906 C33 P40089 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[0 (1429402427406155776)]} 0 1
[junit4:junit4] 2> 24129 T924 C34 P35030 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[0 (1429402427406155776)]} 0 1
[junit4:junit4] 2> 24130 T892 C35 P39830 /update {version=2&wt=javabin} {add=[0 (1429402427406155776)]} 0 5
[junit4:junit4] 2> 24133 T871 C37 P50458 /update {version=2&wt=javabin} {add=[1 (1429402427413495808)]} 0 1
[junit4:junit4] 2> 24138 T907 C33 P40089 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[1 (1429402427416641536)]} 0 0
[junit4:junit4] 2> 24138 T925 C34 P35030 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[1 (1429402427416641536)]} 0 0
[junit4:junit4] 2> 24139 T941 C36 P59635 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[1 (1429402427416641536)]} 0 1
[junit4:junit4] 2> 24139 T889 C35 P39830 /update {version=2&wt=javabin} {add=[1 (1429402427416641536)]} 0 4
[junit4:junit4] 2> 24142 T872 C37 P50458 /update {version=2&wt=javabin} {add=[2 (1429402427423981568)]} 0 1
[junit4:junit4] 2> 24147 T939 C36 P59635 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[2 (1429402427427127296)]} 0 0
[junit4:junit4] 2> 24147 T922 C34 P35030 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[2 (1429402427427127296)]} 0 0
[junit4:junit4] 2> 24148 T891 C35 P39830 /update {version=2&test.distrib.skip.servers=http://127.0.0.1:40089/collection1/&wt=javabin} {add=[2 (1429402427427127296)]} 0 4
[junit4:junit4] 2> 24151 T869 C37 P50458 /update {version=2&wt=javabin} {add=[3 (1429402427432370176)]} 0 1
[junit4:junit4] 2> 24156 T940 C36 P59635 /update {version=2&distrib.from=http://127.0.0.1:39830/collection1/&update.distrib=FROMLEADER&wt=javabin} {add=[3 (1429402427435515904)]} 0 1
[junit4:junit4] 2> 24157 T890 C35 P39830 /update {version=2&test.distrib.skip.servers=http://127.0.0.1:40089/collection1/&test.distrib.skip.servers=http://127.0.0.1:35030/collection1/&wt=javabin} {add=[3 (1429402427435515904)]} 0 4
[junit4:junit4] 2> 24159 T870 C37 P50458 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24164 T870 C37 P50458 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a74403 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fcde68),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a74403 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fcde68),segFN=segments_3,generation=3,filenames=[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, segments_3, _0_Memory_0.ram, _0.nvm, _0_Lucene41WithOrds_0.tii, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24165 T870 C37 P50458 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, segments_3, _0_Memory_0.ram, _0.nvm, _0_Lucene41WithOrds_0.tii, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24166 T870 C37 P50458 oass.SolrIndexSearcher.<init> Opening Searcher@1e68fac main
[junit4:junit4] 2> 24167 T870 C37 P50458 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24168 T880 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e68fac main{StandardDirectoryReader(segments_3:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 24168 T870 C37 P50458 /update {waitSearcher=true&softCommit=false&version=2&commit=true&wt=javabin} {commit=} 0 9
[junit4:junit4] 2> 24171 T892 C35 P39830 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24175 T892 C35 P39830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=5
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f05947 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f750f),segFN=segments_6,generation=6,filenames=[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, _0_Memory_0.ram, _0.nvm, _0_Lucene41WithOrds_0.tii, segments_6, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24176 T892 C35 P39830 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, _0_Memory_0.ram, _0.nvm, _0_Lucene41WithOrds_0.tii, segments_6, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24177 T892 C35 P39830 oass.SolrIndexSearcher.<init> Opening Searcher@8a2c5 main
[junit4:junit4] 2> 24177 T892 C35 P39830 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24178 T898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8a2c5 main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 24178 T892 C35 P39830 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:40089/collection1/, StdNode: http://127.0.0.1:35030/collection1/, StdNode: http://127.0.0.1:59635/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 24181 T942 C36 P59635 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24181 T908 C33 P40089 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24181 T923 C34 P35030 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24184 T908 C33 P40089 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@419ff1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111f9c1),segFN=segments_4,generation=4,filenames=[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, _0_Memory_0.ram, _0.nvm, _0_Lucene41WithOrds_0.tii, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, segments_4, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24185 T908 C33 P40089 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, _0_Memory_0.ram, _0.nvm, _0_Lucene41WithOrds_0.tii, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, segments_4, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24185 T923 C34 P35030 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ecb520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@137ad16),segFN=segments_5,generation=5,filenames=[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, _0_Memory_0.ram, _0.nvm, segments_5, _0_Lucene41WithOrds_0.tii, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24185 T923 C34 P35030 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[_0_Asserting_0.doc, _0_Asserting_0.tim, _0_MockSep_0.pyl, _0_Memory_0.ram, _0.nvm, segments_5, _0_Lucene41WithOrds_0.tii, _0.fdt, _0_MockSep_0.tib, _0_Lucene41WithOrds_0.doc, _0_Asserting_0.pos, _0_MockSep_0.frq, _0_Asserting_0.tip, _0_Lucene41WithOrds_0.pos, _0_MockSep_0.pos, _0_MockSep_0.tii, _0_Lucene41WithOrds_0.tib, _0_MockSep_0.skp, _0_MockSep_0.doc, _0.nvd, _0.fnm, _0.si, _0.fdx]
[junit4:junit4] 2> 24186 T908 C33 P40089 oass.SolrIndexSearcher.<init> Opening Searcher@fcc9e9 main
[junit4:junit4] 2> 24186 T908 C33 P40089 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24187 T923 C34 P35030 oass.SolrIndexSearcher.<init> Opening Searcher@15c21d main
[junit4:junit4] 2> 24187 T914 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@fcc9e9 main{StandardDirectoryReader(segments_4:3:nrt _0(4.3):C2)}
[junit4:junit4] 2> 24187
[...truncated too long message...]
ventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=SimpleText, sim=DefaultSimilarity, locale=sr_BA_#Latn, timezone=America/Paramaribo
[junit4:junit4] 2> NOTE: Linux 3.2.0-38-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=1,free=287873360,total=515899392
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestPropInjectDefaults, PreAnalyzedFieldTest, TestIBSimilarityFactory, FileBasedSpellCheckerTest, FastVectorHighlighterTest, TestGroupingSearch, TestXIncludeConfig, MBeansHandlerTest, SliceStateUpdateTest, TestFieldCollectionResource, TestSort, QueryEqualityTest, IndexSchemaTest, TestLFUCache, TestFuzzyAnalyzedSuggestions, SolrInfoMBeanTest, FieldMutatingUpdateProcessorTest, TestQueryUtils, SolrCoreTest, ResponseLogComponentTest, SpatialFilterTest, ResourceLoaderTest, UpdateRequestProcessorFactoryTest, CSVRequestHandlerTest, DirectSolrConnectionTest, BasicFunctionalityTest, ExternalFileFieldSortTest, TestFastLRUCache, AlternateDirectoryTest, TestPhraseSuggestions, DirectUpdateHandlerOptimizeTest, TestPerFieldSimilarity, PeerSyncTest, TestValueSourceCache, TestStressVersions, SliceStateTest, LoggingHandlerTest, TestFastWriter, BadComponentTest, TestQuerySenderListener, TestJoin, LeaderElectionTest, ZkControllerTest, ShardRoutingTest, SuggesterTest, SyncSliceTest, SynonymTokenizerTest, UnloadDistributedZkTest, BinaryUpdateRequestHandlerTest, TestReversedWildcardFilterFactory, TestLMDirichletSimilarityFactory, DistributedQueryElevationComponentTest, TestSolrIndexConfig, OverseerCollectionProcessorTest, LukeRequestHandlerTest, MinimalSchemaTest, SpellingQueryConverterTest, TestFaceting, TestSolrQueryParser, SchemaVersionSpecificBehaviorTest, SolrIndexSplitterTest, TestCoreContainer, TestTrie, QueryParsingTest, LegacyHTMLStripCharFilterTest, TestFieldTypeResource, CollectionsAPIDistributedZkTest, OpenCloseCoreStressTest, OverseerTest, RecoveryZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.seed=2CC26AE7A4753691 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=sr_BA_#Latn -Dtests.timezone=America/Paramaribo -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 0.00s J0 | RecoveryZkTest (suite) <<<
[junit4:junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=3064, name=coreLoadExecutor-2176-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1569)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:34)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
[junit4:junit4] > at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
[junit4:junit4] > at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:744)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:872)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.create(CoreContainer.java:955)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:579)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4:junit4] > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f80e9f lockFactory=org.apache.lucene.store.NativeFSLockFactory@2f11ac)
[junit4:junit4] > at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4] > at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > ... 1 more
[junit4:junit4] > Throwable #2: com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=3066, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1569)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:34)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
[junit4:junit4] > at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
[junit4:junit4] > at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
[junit4:junit4] > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@13e3506 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f10a73)
[junit4:junit4] > at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4] > at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] Completed on J0 in 34.70s, 1 test, 2 errors <<< FAILURES!
[...truncated 409 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:361: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1213: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:877: There were test failures: 272 suites, 1144 tests, 2 suite-level errors, 1 error, 1 failure, 13 ignored (7 assumptions)
Total time: 51 minutes 0 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.8.0-ea-b79 -client -XX:+UseG1GC -XX:MarkStackSize=256K
Email was triggered for: Failure
Sending email for trigger: Failure