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/21 00:25:47 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b79) - Build #
4799 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4799/
Java: 32bit/jdk1.8.0-ea-b79 -client -XX:+UseG1GC -XX:MarkStackSize=256K
3 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=2926, name=coreLoadExecutor-2383-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=2926, name=coreLoadExecutor-2383-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:524)
at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
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:746)
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@c74417 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c47a50)
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=2928, 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=2928, 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:524)
at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
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@5febe5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b04889)
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)
FAILED: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:46326/gtn/k/onenodecollectioncore returned non ok status:404, message:Can not find: /gtn/k/onenodecollectioncore/update
Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:46326/gtn/k/onenodecollectioncore returned non ok status:404, message:Can not find: /gtn/k/onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([2914D5C30DF344C5:A8F25BDB7AAC24F9]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:487)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 8985 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 0 T375 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /gtn/k
[junit4:junit4] 2> 4 T375 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312
[junit4:junit4] 2> 5 T375 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 5 T376 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 6 T376 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 6 T376 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 6 T376 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 7 T376 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 7 T376 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 105 T375 oasc.ZkTestServer.run start zk server on port:56537
[junit4:junit4] 2> 106 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1fb68cb
[junit4:junit4] 2> 107 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 107 T381 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 107 T381 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 108 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41481
[junit4:junit4] 2> 108 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41481
[junit4:junit4] 2> 108 T379 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 229 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440000 with negotiated timeout 10000 for client /127.0.0.1:41481
[junit4:junit4] 2> 229 T381 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440000, negotiated timeout = 10000
[junit4:junit4] 2> 229 T382 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fb68cb name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 230 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 230 T375 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 233 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440000
[junit4:junit4] 2> 234 T382 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 234 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41481 which had sessionid 0x13d8a10ac440000
[junit4:junit4] 2> 234 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440000 closed
[junit4:junit4] 2> 234 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@13c8144
[junit4:junit4] 2> 235 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 236 T383 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 236 T383 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 236 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41482
[junit4:junit4] 2> 236 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41482
[junit4:junit4] 2> 237 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440001 with negotiated timeout 10000 for client /127.0.0.1:41482
[junit4:junit4] 2> 237 T383 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440001, negotiated timeout = 10000
[junit4:junit4] 2> 237 T384 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13c8144 name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 238 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 238 T375 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 241 T375 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 242 T375 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 244 T375 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 246 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 246 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 249 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 250 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 252 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 253 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 254 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 255 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 256 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 257 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 259 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 259 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 261 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 261 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 263 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 264 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 266 T375 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 266 T375 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 268 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440001
[junit4:junit4] 2> 268 T384 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 268 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41482 which had sessionid 0x13d8a10ac440001
[junit4:junit4] 2> 268 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440001 closed
[junit4:junit4] 2> 336 T375 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 342 T375 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43001
[junit4:junit4] 2> 343 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 343 T375 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 344 T375 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576
[junit4:junit4] 2> 344 T375 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/solr.xml
[junit4:junit4] 2> 344 T375 oasc.CoreContainer.<init> New CoreContainer 14705320
[junit4:junit4] 2> 345 T375 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/'
[junit4:junit4] 2> 345 T375 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/'
[junit4:junit4] 2> 364 T375 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 365 T375 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 365 T375 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 365 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 366 T375 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 366 T375 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 366 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 367 T375 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 367 T375 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 367 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 375 T375 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 389 T375 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56537/solr
[junit4:junit4] 2> 389 T375 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 390 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@4d661b
[junit4:junit4] 2> 391 T394 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 391 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 391 T394 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 391 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41483
[junit4:junit4] 2> 392 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41483
[junit4:junit4] 2> 392 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440002 with negotiated timeout 20000 for client /127.0.0.1:41483
[junit4:junit4] 2> 392 T394 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440002, negotiated timeout = 20000
[junit4:junit4] 2> 393 T395 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4d661b name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 393 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 394 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440002
[junit4:junit4] 2> 394 T395 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 394 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41483 which had sessionid 0x13d8a10ac440002
[junit4:junit4] 2> 394 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440002 closed
[junit4:junit4] 2> 395 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 398 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1874b2a
[junit4:junit4] 2> 399 T396 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 399 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 399 T396 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 399 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41484
[junit4:junit4] 2> 399 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41484
[junit4:junit4] 2> 400 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440003 with negotiated timeout 20000 for client /127.0.0.1:41484
[junit4:junit4] 2> 400 T396 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440003, negotiated timeout = 20000
[junit4:junit4] 2> 401 T397 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1874b2a name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 401 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 402 T375 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 404 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 404 T375 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 406 T375 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 408 T375 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43001_gtn%2Fk
[junit4:junit4] 2> 408 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43001_gtn%2Fk Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43001_gtn%2Fk
[junit4:junit4] 2> 408 T375 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43001_gtn%2Fk
[junit4:junit4] 2> 410 T375 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 414 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 415 T375 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 416 T375 oasc.Overseer.start Overseer (id=89379371831525379-127.0.0.1:43001_gtn%2Fk-n_0000000000) starting
[junit4:junit4] 2> 417 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 417 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 418 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 419 T375 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 420 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 421 T399 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 422 T375 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 423 T375 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 424 T375 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 426 T398 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 428 T400 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/collection1
[junit4:junit4] 2> 428 T400 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 429 T400 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 429 T400 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 430 T400 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/collection1/'
[junit4:junit4] 2> 430 T400 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/collection1/lib/README' to classloader
[junit4:junit4] 2> 431 T400 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 477 T400 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 519 T400 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 520 T400 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 524 T400 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1006 T400 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1013 T400 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1016 T400 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1026 T400 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1029 T400 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1032 T400 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1033 T400 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1034 T400 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1034 T400 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1035 T400 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1035 T400 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1035 T400 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1035 T400 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363820981576/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/
[junit4:junit4] 2> 1036 T400 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@112a254
[junit4:junit4] 2> 1036 T400 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1036 T400 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data forceNew: false
[junit4:junit4] 2> 1037 T400 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/index/
[junit4:junit4] 2> 1037 T400 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1037 T400 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/index forceNew: false
[junit4:junit4] 2> 1039 T400 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8b058d lockFactory=org.apache.lucene.store.NativeFSLockFactory@344b0d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1039 T400 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1040 T400 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1040 T400 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1041 T400 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1041 T400 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1042 T400 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1042 T400 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1042 T400 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1043 T400 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1043 T400 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1046 T400 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1048 T400 oass.SolrIndexSearcher.<init> Opening Searcher@13c2a4a main
[junit4:junit4] 2> 1049 T400 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/tlog
[junit4:junit4] 2> 1049 T400 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1049 T400 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1053 T401 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13c2a4a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1055 T400 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1055 T400 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1928 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1929 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:43001_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43001/gtn/k",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 1929 T398 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1929 T398 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 1932 T397 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> 2056 T400 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2056 T400 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43001/gtn/k collection:control_collection shard:shard1
[junit4:junit4] 2> 2057 T400 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2063 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2063 T400 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2064 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2065 T400 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2065 T400 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2066 T400 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43001/gtn/k/collection1/
[junit4:junit4] 2> 2066 T400 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2066 T400 oasc.SyncStrategy.syncToMe http://127.0.0.1:43001/gtn/k/collection1/ has no replicas
[junit4:junit4] 2> 2066 T400 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43001/gtn/k/collection1/
[junit4:junit4] 2> 2066 T400 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2069 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3435 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3728 T397 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> 3774 T400 oasc.ZkController.register We are http://127.0.0.1:43001/gtn/k/collection1/ and leader is http://127.0.0.1:43001/gtn/k/collection1/
[junit4:junit4] 2> 3775 T400 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43001/gtn/k
[junit4:junit4] 2> 3775 T400 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3775 T400 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3776 T400 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3777 T400 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3778 T375 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3779 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3779 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3782 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3783 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3d9a1f
[junit4:junit4] 2> 3784 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3784 T403 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3784 T403 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 3784 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41485
[junit4:junit4] 2> 3785 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41485
[junit4:junit4] 2> 3786 T403 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440004, negotiated timeout = 10000
[junit4:junit4] 2> 3786 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440004 with negotiated timeout 10000 for client /127.0.0.1:41485
[junit4:junit4] 2> 3786 T404 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d9a1f name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3786 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3788 T375 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3789 T375 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3849 T375 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3851 T375 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48555
[junit4:junit4] 2> 3852 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3852 T375 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3853 T375 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097
[junit4:junit4] 2> 3853 T375 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/solr.xml
[junit4:junit4] 2> 3853 T375 oasc.CoreContainer.<init> New CoreContainer 977909
[junit4:junit4] 2> 3854 T375 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/'
[junit4:junit4] 2> 3854 T375 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/'
[junit4:junit4] 2> 3873 T375 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3873 T375 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3874 T375 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3874 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3874 T375 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3875 T375 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3875 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3876 T375 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3876 T375 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3876 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3883 T375 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3896 T375 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56537/solr
[junit4:junit4] 2> 3896 T375 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3897 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@d92539
[junit4:junit4] 2> 3897 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3898 T414 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3898 T414 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 3898 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41486
[junit4:junit4] 2> 3899 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41486
[junit4:junit4] 2> 3900 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440005 with negotiated timeout 20000 for client /127.0.0.1:41486
[junit4:junit4] 2> 3900 T414 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440005, negotiated timeout = 20000
[junit4:junit4] 2> 3900 T415 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d92539 name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3901 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3902 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440005
[junit4:junit4] 2> 3902 T415 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3902 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41486 which had sessionid 0x13d8a10ac440005
[junit4:junit4] 2> 3902 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440005 closed
[junit4:junit4] 2> 3903 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3905 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@115a62b
[junit4:junit4] 2> 3906 T416 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3906 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3907 T416 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 3907 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41487
[junit4:junit4] 2> 3907 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41487
[junit4:junit4] 2> 3908 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440006 with negotiated timeout 20000 for client /127.0.0.1:41487
[junit4:junit4] 2> 3908 T416 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440006, negotiated timeout = 20000
[junit4:junit4] 2> 3908 T417 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@115a62b name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3908 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3909 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3910 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3912 T375 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4914 T375 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48555_gtn%2Fk
[junit4:junit4] 2> 4915 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:48555_gtn%2Fk Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:48555_gtn%2Fk
[junit4:junit4] 2> 4917 T375 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48555_gtn%2Fk
[junit4:junit4] 2> 4921 T397 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 4922 T404 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4922 T417 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4924 T397 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4931 T418 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/collection1
[junit4:junit4] 2> 4932 T418 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4933 T418 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4933 T418 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4935 T418 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/collection1/'
[junit4:junit4] 2> 4936 T418 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/collection1/lib/README' to classloader
[junit4:junit4] 2> 4937 T418 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4980 T418 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 5019 T418 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5020 T418 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5025 T418 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5230 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5230 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:43001_gtn%2Fk",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43001/gtn/k",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 5233 T397 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> 5233 T404 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> 5233 T417 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> 5479 T418 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5485 T418 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5489 T418 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5503 T418 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5508 T418 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5513 T418 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5514 T418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5515 T418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5515 T418 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5516 T418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5516 T418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5517 T418 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5517 T418 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/
[junit4:junit4] 2> 5518 T418 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@112a254
[junit4:junit4] 2> 5518 T418 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5519 T418 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1 forceNew: false
[junit4:junit4] 2> 5519 T418 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/index/
[junit4:junit4] 2> 5519 T418 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5520 T418 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/index forceNew: false
[junit4:junit4] 2> 5522 T418 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2713e lockFactory=org.apache.lucene.store.NativeFSLockFactory@16e6721),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5522 T418 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5525 T418 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5525 T418 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5526 T418 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5527 T418 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5528 T418 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5528 T418 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5529 T418 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5530 T418 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5530 T418 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5534 T418 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5538 T418 oass.SolrIndexSearcher.<init> Opening Searcher@3330f1 main
[junit4:junit4] 2> 5539 T418 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/tlog
[junit4:junit4] 2> 5539 T418 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5540 T418 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5544 T419 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3330f1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5547 T418 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5548 T418 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6736 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6737 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:48555_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48555/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 6737 T398 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 6737 T398 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 6838 T417 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> 6838 T404 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> 6838 T397 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> 7549 T418 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7549 T418 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48555/gtn/k collection:collection1 shard:shard2
[junit4:junit4] 2> 7550 T418 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 7555 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:delete cxid:0x4a zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7556 T418 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7556 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7559 T418 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7560 T418 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7560 T418 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48555/gtn/k/collection1/
[junit4:junit4] 2> 7560 T418 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7560 T418 oasc.SyncStrategy.syncToMe http://127.0.0.1:48555/gtn/k/collection1/ has no replicas
[junit4:junit4] 2> 7560 T418 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48555/gtn/k/collection1/
[junit4:junit4] 2> 7561 T418 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 7565 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8343 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8358 T397 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> 8358 T404 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> 8358 T417 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> 8368 T418 oasc.ZkController.register We are http://127.0.0.1:48555/gtn/k/collection1/ and leader is http://127.0.0.1:48555/gtn/k/collection1/
[junit4:junit4] 2> 8368 T418 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48555/gtn/k
[junit4:junit4] 2> 8368 T418 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8368 T418 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8369 T418 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8370 T418 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8371 T375 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 8371 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8371 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8443 T375 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8445 T375 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46326
[junit4:junit4] 2> 8445 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8446 T375 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8446 T375 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683
[junit4:junit4] 2> 8446 T375 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/solr.xml
[junit4:junit4] 2> 8447 T375 oasc.CoreContainer.<init> New CoreContainer 25550409
[junit4:junit4] 2> 8447 T375 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/'
[junit4:junit4] 2> 8448 T375 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/'
[junit4:junit4] 2> 8466 T375 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8467 T375 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8467 T375 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8467 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8468 T375 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8468 T375 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8468 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8469 T375 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8469 T375 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8469 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8477 T375 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8497 T375 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56537/solr
[junit4:junit4] 2> 8498 T375 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8498 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1917b5e
[junit4:junit4] 2> 8499 T430 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8499 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8500 T430 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 8500 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41517
[junit4:junit4] 2> 8500 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41517
[junit4:junit4] 2> 8501 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440007 with negotiated timeout 20000 for client /127.0.0.1:41517
[junit4:junit4] 2> 8501 T430 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440007, negotiated timeout = 20000
[junit4:junit4] 2> 8501 T431 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1917b5e name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8501 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8503 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440007
[junit4:junit4] 2> 8503 T431 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8503 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41517 which had sessionid 0x13d8a10ac440007
[junit4:junit4] 2> 8503 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440007 closed
[junit4:junit4] 2> 8504 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8506 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@141b150
[junit4:junit4] 2> 8507 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8508 T432 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8508 T432 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 8508 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41518
[junit4:junit4] 2> 8509 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41518
[junit4:junit4] 2> 8509 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440008 with negotiated timeout 20000 for client /127.0.0.1:41518
[junit4:junit4] 2> 8509 T432 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440008, negotiated timeout = 20000
[junit4:junit4] 2> 8510 T433 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@141b150 name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8510 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8511 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8512 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8513 T375 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9515 T375 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46326_gtn%2Fk
[junit4:junit4] 2> 9517 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:46326_gtn%2Fk Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:46326_gtn%2Fk
[junit4:junit4] 2> 9518 T375 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46326_gtn%2Fk
[junit4:junit4] 2> 9523 T433 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9523 T397 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9523 T404 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9523 T397 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> 9523 T404 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> 9524 T417 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9524 T417 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> 9537 T434 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/collection1
[junit4:junit4] 2> 9538 T434 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9539 T434 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9539 T434 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9541 T434 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/collection1/'
[junit4:junit4] 2> 9542 T434 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/collection1/lib/README' to classloader
[junit4:junit4] 2> 9543 T434 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9600 T434 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9647 T434 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9649 T434 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9653 T434 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9864 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9865 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:48555_gtn%2Fk",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48555/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 9867 T404 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> 9867 T397 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> 9867 T417 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> 9867 T433 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> 10129 T434 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10136 T434 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10139 T434 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10149 T434 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10152 T434 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10155 T434 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10155 T434 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10156 T434 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10156 T434 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10157 T434 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10157 T434 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10157 T434 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10158 T434 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363820989683/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty2/
[junit4:junit4] 2> 10158 T434 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@112a254
[junit4:junit4] 2> 10158 T434 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10159 T434 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty2 forceNew: false
[junit4:junit4] 2> 10159 T434 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty2/index/
[junit4:junit4] 2> 10159 T434 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10160 T434 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty2/index forceNew: false
[junit4:junit4] 2> 10161 T434 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16c1862 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3724b5),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10161 T434 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10163 T434 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10163 T434 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10164 T434 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10164 T434 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10165 T434 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10165 T434 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10165 T434 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10166 T434 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10166 T434 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10169 T434 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10172 T434 oass.SolrIndexSearcher.<init> Opening Searcher@152a971 main
[junit4:junit4] 2> 10172 T434 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty2/tlog
[junit4:junit4] 2> 10173 T434 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10173 T434 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10178 T435 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@152a971 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10185 T434 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10185 T434 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11370 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11371 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:46326_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46326/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 11372 T398 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 11372 T398 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11375 T417 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> 11375 T404 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> 11375 T397 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> 11375 T433 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> 12191 T434 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 12192 T434 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46326/gtn/k collection:collection1 shard:shard1
[junit4:junit4] 2> 12193 T434 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 12201 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4] 2> 12201 T434 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 12202 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12205 T434 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 12206 T434 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 12206 T434 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46326/gtn/k/collection1/
[junit4:junit4] 2> 12206 T434 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 12207 T434 oasc.SyncStrategy.syncToMe http://127.0.0.1:46326/gtn/k/collection1/ has no replicas
[junit4:junit4] 2> 12207 T434 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46326/gtn/k/collection1/
[junit4:junit4] 2> 12208 T434 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 12212 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12881 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12893 T397 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> 12893 T417 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> 12893 T404 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> 12893 T433 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> 12917 T434 oasc.ZkController.register We are http://127.0.0.1:46326/gtn/k/collection1/ and leader is http://127.0.0.1:46326/gtn/k/collection1/
[junit4:junit4] 2> 12917 T434 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46326/gtn/k
[junit4:junit4] 2> 12917 T434 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 12918 T434 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 12918 T434 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12920 T434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12922 T375 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 12922 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 12923 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13004 T375 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 13006 T375 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37049
[junit4:junit4] 2> 13007 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 13008 T375 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 13008 T375 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238
[junit4:junit4] 2> 13008 T375 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/solr.xml
[junit4:junit4] 2> 13009 T375 oasc.CoreContainer.<init> New CoreContainer 12292001
[junit4:junit4] 2> 13009 T375 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/'
[junit4:junit4] 2> 13009 T375 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/'
[junit4:junit4] 2> 13032 T375 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 13032 T375 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 13032 T375 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 13033 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 13033 T375 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 13033 T375 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 13034 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 13034 T375 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 13034 T375 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 13035 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 13042 T375 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 13054 T375 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56537/solr
[junit4:junit4] 2> 13054 T375 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 13055 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1867188
[junit4:junit4] 2> 13055 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13056 T446 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13056 T446 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 13056 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41524
[junit4:junit4] 2> 13057 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41524
[junit4:junit4] 2> 13058 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac440009 with negotiated timeout 20000 for client /127.0.0.1:41524
[junit4:junit4] 2> 13058 T446 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac440009, negotiated timeout = 20000
[junit4:junit4] 2> 13059 T447 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1867188 name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13059 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13060 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440009
[junit4:junit4] 2> 13060 T447 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 13060 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41524 which had sessionid 0x13d8a10ac440009
[junit4:junit4] 2> 13060 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440009 closed
[junit4:junit4] 2> 13061 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 13064 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1f322e4
[junit4:junit4] 2> 13066 T448 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13066 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13067 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41525
[junit4:junit4] 2> 13066 T448 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 13068 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41525
[junit4:junit4] 2> 13068 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac44000a with negotiated timeout 20000 for client /127.0.0.1:41525
[junit4:junit4] 2> 13068 T448 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac44000a, negotiated timeout = 20000
[junit4:junit4] 2> 13069 T449 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f322e4 name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13069 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13070 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac44000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13072 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac44000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13074 T375 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 14078 T375 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37049_gtn%2Fk
[junit4:junit4] 2> 14079 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac44000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:37049_gtn%2Fk Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:37049_gtn%2Fk
[junit4:junit4] 2> 14080 T375 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37049_gtn%2Fk
[junit4:junit4] 2> 14083 T433 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> 14084 T397 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> 14084 T404 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> 14085 T449 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14084 T417 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> 14087 T433 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14088 T404 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14089 T397 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14089 T417 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14096 T450 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/collection1
[junit4:junit4] 2> 14097 T450 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 14098 T450 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 14098 T450 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 14100 T450 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/collection1/'
[junit4:junit4] 2> 14100 T450 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/collection1/lib/README' to classloader
[junit4:junit4] 2> 14100 T450 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 14133 T450 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 14180 T450 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 14182 T450 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 14186 T450 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 14400 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14401 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:46326_gtn%2Fk",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46326/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 14404 T397 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> 14404 T404 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> 14404 T449 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> 14404 T433 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> 14404 T417 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> 14611 T450 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 14617 T450 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 14620 T450 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 14637 T450 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14643 T450 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14649 T450 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14651 T450 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 14652 T450 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 14652 T450 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14654 T450 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 14654 T450 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 14655 T450 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14655 T450 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363820994238/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3/
[junit4:junit4] 2> 14656 T450 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@112a254
[junit4:junit4] 2> 14656 T450 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14657 T450 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3 forceNew: false
[junit4:junit4] 2> 14658 T450 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3/index/
[junit4:junit4] 2> 14658 T450 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 14659 T450 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3/index forceNew: false
[junit4:junit4] 2> 14661 T450 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1774288 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111d32f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 14662 T450 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 14666 T450 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 14666 T450 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 14667 T450 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 14669 T450 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 14670 T450 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 14670 T450 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 14671 T450 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 14672 T450 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 14673 T450 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 14679 T450 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 14690 T450 oass.SolrIndexSearcher.<init> Opening Searcher@152b862 main
[junit4:junit4] 2> 14690 T450 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3/tlog
[junit4:junit4] 2> 14691 T450 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 14691 T450 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 14696 T451 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@152b862 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 14697 T450 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 14698 T450 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15908 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15910 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:37049_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37049/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 15910 T398 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 15910 T398 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 15915 T417 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> 15916 T433 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> 15915 T449 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> 15915 T404 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> 15915 T397 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> 16699 T450 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 16700 T450 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37049/gtn/k collection:collection1 shard:shard2
[junit4:junit4] 2> 16705 T450 oasc.ZkController.register We are http://127.0.0.1:37049/gtn/k/collection1/ and leader is http://127.0.0.1:48555/gtn/k/collection1/
[junit4:junit4] 2> 16706 T450 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37049/gtn/k
[junit4:junit4] 2> 16706 T450 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 16706 T450 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C27 name=collection1 org.apache.solr.core.SolrCore@11cb915 url=http://127.0.0.1:37049/gtn/k/collection1 node=127.0.0.1:37049_gtn%2Fk C27_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:37049_gtn%2Fk, state=down, core=collection1, collection=collection1, base_url=http://127.0.0.1:37049/gtn/k}
[junit4:junit4] 2> 16707 T452 C27 P37049 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 16708 T450 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16708 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 16709 T452 C27 P37049 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 16709 T452 C27 P37049 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16710 T375 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 16711 T452 C27 P37049 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16711 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 16712 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16790 T375 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 16792 T375 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34003
[junit4:junit4] 2> 16793 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 16793 T375 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 16794 T375 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025
[junit4:junit4] 2> 16794 T375 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/solr.xml
[junit4:junit4] 2> 16794 T375 oasc.CoreContainer.<init> New CoreContainer 27367551
[junit4:junit4] 2> 16795 T375 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/'
[junit4:junit4] 2> 16795 T375 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/'
[junit4:junit4] 2> 16816 T375 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 16816 T375 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 16816 T375 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 16817 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 16817 T375 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 16817 T375 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 16818 T375 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 16818 T375 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 16818 T375 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 16819 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 16825 T375 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 16837 T375 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56537/solr
[junit4:junit4] 2> 16838 T375 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 16838 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@20205b
[junit4:junit4] 2> 16839 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16839 T463 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 16840 T463 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 16840 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41529
[junit4:junit4] 2> 16840 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41529
[junit4:junit4] 2> 16841 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac44000b with negotiated timeout 20000 for client /127.0.0.1:41529
[junit4:junit4] 2> 16841 T463 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac44000b, negotiated timeout = 20000
[junit4:junit4] 2> 16842 T464 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20205b name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16842 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16843 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac44000b
[junit4:junit4] 2> 16844 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41529 which had sessionid 0x13d8a10ac44000b
[junit4:junit4] 2> 16844 T464 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 16844 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac44000b closed
[junit4:junit4] 2> 16845 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 16850 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@15d9ef1
[junit4:junit4] 2> 16851 T465 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 16851 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16852 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41530
[junit4:junit4] 2> 16852 T465 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 16853 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41530
[junit4:junit4] 2> 16853 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac44000c with negotiated timeout 20000 for client /127.0.0.1:41530
[junit4:junit4] 2> 16854 T465 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac44000c, negotiated timeout = 20000
[junit4:junit4] 2> 16854 T466 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15d9ef1 name:ZooKeeperConnection Watcher:127.0.0.1:56537/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16854 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16855 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac44000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16857 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac44000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16859 T375 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 17423 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17424 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:37049_gtn%2Fk",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37049/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 17429 T466 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> 17430 T404 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> 17429 T433 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> 17430 T449 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> 17429 T397 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> 17429 T417 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> 17719 T412 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=4&nodeName=127.0.0.1:37049_gtn%252Fk&state=recovering&action=PREPRECOVERY&core=collection1&onlyIfLeader=true&checkLive=true&version=2&wt=javabin} status=0 QTime=1000
[junit4:junit4] 2> 17863 T375 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34003_gtn%2Fk
[junit4:junit4] 2> 17864 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac44000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:34003_gtn%2Fk Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:34003_gtn%2Fk
[junit4:junit4] 2> 17865 T375 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34003_gtn%2Fk
[junit4:junit4] 2> 17868 T397 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> 17869 T404 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> 17870 T449 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17870 T433 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17871 T466 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17870 T417 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17871 T433 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> 17871 T449 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> 17872 T417 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> 17871 T466 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> 17873 T404 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17873 T397 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17882 T467 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/collection1
[junit4:junit4] 2> 17882 T467 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 17883 T467 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 17884 T467 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 17885 T467 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/collection1/'
[junit4:junit4] 2> 17886 T467 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/collection1/lib/README' to classloader
[junit4:junit4] 2> 17887 T467 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 17921 T467 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 17965 T467 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 17966 T467 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 17971 T467 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 18411 T467 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 18417 T467 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 18420 T467 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 18433 T467 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18436 T467 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18439 T467 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18440 T467 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18440 T467 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 18440 T467 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18441 T467 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18441 T467 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 18441 T467 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 18441 T467 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363820998025/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4/
[junit4:junit4] 2> 18442 T467 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@112a254
[junit4:junit4] 2> 18442 T467 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 18442 T467 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4 forceNew: false
[junit4:junit4] 2> 18443 T467 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4/index/
[junit4:junit4] 2> 18443 T467 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 18444 T467 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4/index forceNew: false
[junit4:junit4] 2> 18446 T467 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58a499 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fc2e57),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 18446 T467 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 18448 T467 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 18449 T467 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 18449 T467 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 18450 T467 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 18451 T467 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 18451 T467 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 18452 T467 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 18453 T467 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 18453 T467 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 18457 T467 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 18460 T467 oass.SolrIndexSearcher.<init> Opening Searcher@15c0f87 main
[junit4:junit4] 2> 18461 T467 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4/tlog
[junit4:junit4] 2> 18461 T467 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 18461 T467 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 18470 T468 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15c0f87 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 18474 T467 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 18474 T467 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18935 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18936 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:34003_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34003/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 18936 T398 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 18936 T398 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 18938 T449 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> 18939 T433 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> 18939 T404 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> 18939 T466 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> 18939 T417 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> 18939 T397 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> 19476 T467 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 19476 T467 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34003/gtn/k collection:collection1 shard:shard1
[junit4:junit4] 2> 19480 T467 oasc.ZkController.register We are http://127.0.0.1:34003/gtn/k/collection1/ and leader is http://127.0.0.1:46326/gtn/k/collection1/
[junit4:junit4] 2> 19480 T467 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34003/gtn/k
[junit4:junit4] 2> 19480 T467 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 19480 T467 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C28 name=collection1 org.apache.solr.core.SolrCore@1e5853c url=http://127.0.0.1:34003/gtn/k/collection1 node=127.0.0.1:34003_gtn%2Fk C28_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:34003_gtn%2Fk, state=down, core=collection1, collection=collection1, base_url=http://127.0.0.1:34003/gtn/k}
[junit4:junit4] 2> 19480 T469 C28 P34003 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 19481 T467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19481 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 19481 T469 C28 P34003 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 19481 T469 C28 P34003 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19482 T375 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 19482 T375 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 19483 T469 C28 P34003 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19482 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19486 T375 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19487 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19491 T410 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/onenodecollectioncore
[junit4:junit4] 2> 19491 T410 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 19493 T410 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 19493 T410 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 19495 T410 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 19496 T410 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 19499 T410 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 19500 T410 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/onenodecollectioncore/'
[junit4:junit4] 2> 19540 T410 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 19578 T410 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 19579 T410 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 19583 T410 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> C27_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:37049_gtn%2Fk, state=recovering, core=collection1, collection=collection1, shard=shard2, base_url=http://127.0.0.1:37049/gtn/k}
[junit4:junit4] 2> 19721 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:48555/gtn/k/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 19721 T452 C27 P37049 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:37049/gtn/k START replicas=[http://127.0.0.1:48555/gtn/k/collection1/] nUpdates=100
[junit4:junit4] 2> 19721 T452 C27 P37049 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 19722 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 19722 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 19722 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 19722 T452 C27 P37049 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 19723 T452 C27 P37049 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:48555/gtn/k/collection1/. core=collection1
[junit4:junit4] 2> 19723 T452 C27 P37049 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C29 name=collection1 org.apache.solr.core.SolrCore@13a453d url=http://127.0.0.1:48555/gtn/k/collection1 node=127.0.0.1:48555_gtn%2Fk C29_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:48555_gtn%2Fk, state=active, core=collection1, collection=collection1, shard=shard2, base_url=http://127.0.0.1:48555/gtn/k, leader=true}
[junit4:junit4] 2> 19728 T413 C29 P48555 REQ /get {getVersions=100&qt=/get&version=2&wt=javabin&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 19739 T411 C29 P48555 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 19740 T411 C29 P48555 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2713e lockFactory=org.apache.lucene.store.NativeFSLockFactory@16e6721),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 19741 T411 C29 P48555 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 19741 T411 C29 P48555 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2713e lockFactory=org.apache.lucene.store.NativeFSLockFactory@16e6721),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2713e lockFactory=org.apache.lucene.store.NativeFSLockFactory@16e6721),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19742 T411 C29 P48555 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19742 T411 C29 P48555 oass.SolrIndexSearcher.<init> Opening Searcher@ca90de realtime
[junit4:junit4] 2> 19742 T411 C29 P48555 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19743 T411 C29 P48555 /update {softCommit=false&commit_end_point=true&commit=true&openSearcher=false&version=2&waitSearcher=true&wt=javabin} {commit=} 0 4
[junit4:junit4] 2> 19744 T452 C27 P37049 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19744 T452 C27 P37049 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 19748 T412 C29 P48555 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19748 T412 C29 P48555 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=3
[junit4:junit4] 2> 19749 T452 C27 P37049 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 19749 T452 C27 P37049 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 19749 T452 C27 P37049 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 19751 T411 C29 P48555 REQ /replication {generation=2&qt=/replication&version=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 19752 T452 C27 P37049 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 19753 T452 C27 P37049 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty3/index.20130321021001060 forceNew: false
[junit4:junit4] 2> 19753 T452 C27 P37049 oash.SnapPuller.fetchLatestIndex Starting download to BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@cf3f91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9f48ab) fullCopy=false
[junit4:junit4] 2> 19755 T413 C29 P48555 REQ /replication {file=segments_2&generation=2&qt=/replication&command=filecontent&wt=filestream&checksum=true} status=0 QTime=0
[junit4:junit4] 2> 19756 T452 C27 P37049 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 19757 T452 C27 P37049 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 19758 T452 C27 P37049 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 19759 T452 C27 P37049 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1774288 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111d32f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1774288 lockFactory=org.apache.lucene.store.NativeFSLockFactory@111d32f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19760 T452 C27 P37049 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19760 T452 C27 P37049 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 19761 T452 C27 P37049 oass.SolrIndexSearcher.<init> Opening Searcher@ba1577 main
[junit4:junit4] 2> 19763 T451 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ba1577 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 19763 T452 C27 P37049 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 19764 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 19764 T452 C27 P37049 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 19765 T452 C27 P37049 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19766 T452 C27 P37049 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 20055 T410 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 20061 T410 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 20064 T410 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 20077 T410 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 20082 T410 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 20088 T410 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 20090 T410 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 20090 T410 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 20091 T410 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 20092 T410 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 20093 T410 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 20094 T410 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 20094 T410 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363820985097/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection/
[junit4:junit4] 2> 20095 T410 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@112a254
[junit4:junit4] 2> 20096 T410 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 20097 T410 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection forceNew: false
[junit4:junit4] 2> 20098 T410 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection/index/
[junit4:junit4] 2> 20099 T410 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 20099 T410 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection/index forceNew: false
[junit4:junit4] 2> 20101 T410 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c962 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8a92d2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 20101 T410 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 20103 T410 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 20103 T410 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 20104 T410 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 20105 T410 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 20105 T410 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 20105 T410 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 20106 T410 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 20106 T410 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 20107 T410 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 20109 T410 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 20112 T410 oass.SolrIndexSearcher.<init> Opening Searcher@4967d6 main
[junit4:junit4] 2> 20113 T410 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection/tlog
[junit4:junit4] 2> 20113 T410 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 20114 T410 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 20117 T473 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@4967d6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 20118 T410 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 20444 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20446 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:34003_gtn%2Fk",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34003/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 20451 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:37049_gtn%2Fk",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37049/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 20456 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:48555_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"onenodecollectioncore",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48555/gtn/k",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 20456 T398 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 20456 T398 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 20462 T397 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> 20462 T466 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> 20462 T417 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> 20462 T433 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> 20462 T449 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> 20463 T404 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> 20487 T427 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=5&nodeName=127.0.0.1:34003_gtn%252Fk&state=recovering&action=PREPRECOVERY&core=collection1&onlyIfLeader=true&checkLive=true&version=2&wt=javabin} status=0 QTime=1000
[junit4:junit4] 2> 21120 T410 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 21120 T410 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:48555/gtn/k collection:onenodecollection shard:shard1
[junit4:junit4] 2> 21121 T410 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 21126 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:delete cxid:0xac zxid:0xc2 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4] 2> 21126 T410 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 21127 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 21128 T410 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 21129 T410 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 21129 T410 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48555/gtn/k/onenodecollectioncore/
[junit4:junit4] 2> 21129 T410 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 21129 T410 oasc.SyncStrategy.syncToMe http://127.0.0.1:48555/gtn/k/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 21130 T410 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48555/gtn/k/onenodecollectioncore/
[junit4:junit4] 2> 21130 T410 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 21133 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 21985 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21994 T397 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> 21994 T449 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> 21994 T417 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> 21994 T466 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> 21995 T433 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> 21994 T404 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> 22037 T410 oasc.ZkController.register We are http://127.0.0.1:48555/gtn/k/onenodecollectioncore/ and leader is http://127.0.0.1:48555/gtn/k/onenodecollectioncore/
[junit4:junit4] 2> 22037 T410 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:48555/gtn/k
[junit4:junit4] 2> 22038 T410 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 22039 T410 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 22041 T410 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22042 T410 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {action=CREATE&collection=onenodecollection&name=onenodecollectioncore&version=2&numShards=1&roles=none&wt=javabin&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363820981312/onenodecollection} status=0 QTime=2552
[junit4:junit4] 2> 22044 T375 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 22045 T375 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C28_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:34003_gtn%2Fk, state=recovering, core=collection1, collection=collection1, shard=shard1, base_url=http://127.0.0.1:34003/gtn/k}
[junit4:junit4] 2> 22488 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46326/gtn/k/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 22489 T469 C28 P34003 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34003/gtn/k START replicas=[http://127.0.0.1:46326/gtn/k/collection1/] nUpdates=100
[junit4:junit4] 2> 22489 T469 C28 P34003 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 22490 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 22490 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 22490 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 22491 T469 C28 P34003 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 22491 T469 C28 P34003 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46326/gtn/k/collection1/. core=collection1
[junit4:junit4] 2> 22491 T469 C28 P34003 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C30 name=collection1 org.apache.solr.core.SolrCore@1c749fb url=http://127.0.0.1:46326/gtn/k/collection1 node=127.0.0.1:46326_gtn%2Fk C30_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:46326_gtn%2Fk, state=active, core=collection1, collection=collection1, shard=shard1, base_url=http://127.0.0.1:46326/gtn/k, leader=true}
[junit4:junit4] 2> 22499 T428 C30 P46326 REQ /get {getVersions=100&qt=/get&version=2&wt=javabin&distrib=false} status=0 QTime=1
[junit4:junit4] 2> 22499 T429 C30 P46326 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22502 T429 C30 P46326 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16c1862 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3724b5),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22503 T429 C30 P46326 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22504 T429 C30 P46326 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16c1862 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3724b5),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16c1862 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3724b5),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22504 T429 C30 P46326 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22505 T429 C30 P46326 oass.SolrIndexSearcher.<init> Opening Searcher@1c5387b realtime
[junit4:junit4] 2> 22506 T429 C30 P46326 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22506 T429 C30 P46326 /update {softCommit=false&commit_end_point=true&commit=true&openSearcher=false&version=2&waitSearcher=true&wt=javabin} {commit=} 0 7
[junit4:junit4] 2> 22508 T469 C28 P34003 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 22508 T469 C28 P34003 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 22510 T427 C30 P46326 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 22511 T427 C30 P46326 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 22512 T469 C28 P34003 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 22512 T469 C28 P34003 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 22513 T469 C28 P34003 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 22515 T428 C30 P46326 REQ /replication {generation=2&qt=/replication&version=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 22516 T469 C28 P34003 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 22518 T469 C28 P34003 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty4/index.20130321021003825 forceNew: false
[junit4:junit4] 2> 22518 T469 C28 P34003 oash.SnapPuller.fetchLatestIndex Starting download to BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@85c3b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2b5014) fullCopy=false
[junit4:junit4] 2> 22521 T429 C30 P46326 REQ /replication {file=segments_2&generation=2&qt=/replication&command=filecontent&wt=filestream&checksum=true} status=0 QTime=0
[junit4:junit4] 2> 22535 T469 C28 P34003 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 22537 T469 C28 P34003 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 22537 T469 C28 P34003 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 22539 T469 C28 P34003 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58a499 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fc2e57),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58a499 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fc2e57),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22540 T469 C28 P34003 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22540 T469 C28 P34003 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 22541 T469 C28 P34003 oass.SolrIndexSearcher.<init> Opening Searcher@113604 main
[junit4:junit4] 2> 22543 T468 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@113604 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22544 T469 C28 P34003 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 22544 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 22545 T469 C28 P34003 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 22545 T469 C28 P34003 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 22546 T469 C28 P34003 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 23047 T375 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23502 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23503 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"127.0.0.1:48555_gtn%2Fk_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:48555_gtn%2Fk",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"onenodecollectioncore",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48555/gtn/k",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 23508 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:34003_gtn%2Fk",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34003/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 23513 T433 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> 23514 T417 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> 23514 T404 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> 23513 T466 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> 23514 T397 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> 23514 T449 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> 24050 T375 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 24051 T375 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 24052 T375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 24071 T375 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56537 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@79165c
[junit4:junit4] 2> 24073 T375 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 24073 T476 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56537. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 24074 T476 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56537, initiating session
[junit4:junit4] 2> 24074 T377 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41544
[junit4:junit4] 2> 24075 T377 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41544
[junit4:junit4] 2> 24076 T379 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8a10ac44000d with negotiated timeout 10000 for client /127.0.0.1:41544
[junit4:junit4] 2> 24076 T476 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56537, sessionid = 0x13d8a10ac44000d, negotiated timeout = 10000
[junit4:junit4] 2> 24077 T477 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@79165c name:ZooKeeperConnection Watcher:127.0.0.1:56537 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 24077 T375 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 24138 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac44000d
[junit4:junit4] 2> 24139 T477 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 24139 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41544 which had sessionid 0x13d8a10ac44000d
[junit4:junit4] 2> 24139 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac44000d closed
[junit4:junit4] 2> 24140 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440004
[junit4:junit4] 2> 24141 T404 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 24141 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440004 closed
[junit4:junit4] 2> 24141 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41485 which had sessionid 0x13d8a10ac440004
[junit4:junit4] 2> 24146 T375 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 43001
[junit4:junit4] 2> 24146 T375 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=14705320
[junit4:junit4] 2> 25022 T398 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 25024 T398 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:43001_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43001/gtn/k",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 25030 T449 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> 25030 T466 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> 25030 T433 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> 25030 T397 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> 25030 T417 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> 26148 T375 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 26149 T375 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 26153 T375 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@e1166
[junit4:junit4] 2> 26161 T375 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 26161 T375 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 26162 T375 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 26163 T375 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 26164 T375 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 26165 T375 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data
[junit4:junit4] 2> 26166 T375 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data
[junit4:junit4] 2> 26166 T375 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/index
[junit4:junit4] 2> 26167 T375 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/control/data/index
[junit4:junit4] 2> 26169 T398 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89379371831525379-127.0.0.1:43001_gtn%2Fk-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 26169 T380 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8a10ac440003
[junit4:junit4] 2> 26170 T397 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> 26170 T433 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> 26170 T417 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 26170 T375 oaz.ZooKeeper.close Session: 0x13d8a10ac440003 closed
[junit4:junit4] 2> 26170 T449 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> 26170 T466 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> 26171 T417 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> 26171 T377 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41484 which had sessionid 0x13d8a10ac440003
[junit4:junit4] 2> 26170 T397 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 26172 T397 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 26173 T397 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 26174 T449 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 26174 T433 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 26174 T466 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 26175 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:delete cxid:0xc9 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 26176 T417 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 26178 T417 oasc.Overseer.start Overseer (id=89379371831525382-127.0.0.1:48555_gtn%2Fk-n_0000000001) starting
[junit4:junit4] 2> 26179 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0xce zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 26180 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0xcf zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 26182 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0xd1 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 26184 T380 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8a10ac440006 type:create cxid:0xd3 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 26185 T479 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 26185 T478 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 26187 T478 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 26188 T478 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:43001_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43001/gtn/k",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 26193 T417 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> 26193 T433 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> 26193 T449 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> 26195 T375 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/gtn/k,null}
[junit4:junit4] 2> 26193 T466 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> 26248 T375 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 48555
[junit4:junit4] 2> 26248 T375 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=977909
[junit4:junit4] 2> 27699 T478 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 27701 T478 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "core_node_name":"127.0.0.1:48555_gtn%2Fk_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:48555_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"onenodecollectioncore",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48555/gtn/k",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 27705 T478 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:48555_gtn%2Fk",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48555/gtn/k",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 27710 T449 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> 27710 T417 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> 27710 T466 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> 27710 T433 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> 29251 T375 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 29252 T375 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 29254 T375 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 29258 T375 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@13a453d
[junit4:junit4] 2> 29265 T375 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 29266 T375 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 29266 T375 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 29267 T375 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 29269 T375 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 29270 T375 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1
[junit4:junit4] 2> 29271 T375 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1
[junit4:junit4] 2> 29272 T375 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/index
[junit4:junit4] 2> 29272 T375 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363820981312/jetty1/index
[junit4:junit4] 2> 29273 T375 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@14dd767
[junit4:junit4] 2> 29282 T375 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 29282 T375 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 29282 T375 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 29283 T375 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 29283 T375 oasc.SolrCore.closeSearcher [oneno
[...truncated too long message...]
ormat(name=MockSep), range_facet_l=PostingsFormat(name=MockSep)}, docValues:{timestamp=DocValuesFormat(name=SimpleText)}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=sr_CS, timezone=Navajo
[junit4:junit4] 2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=3,free=353360920,total=486539264
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DirectSolrSpellCheckerTest, OutputWriterTest, SampleTest, TestDynamicFieldResource, CoreContainerCoreInitFailuresTest, NumericFieldsTest, TestQueryTypes, TestBM25SimilarityFactory, XsltUpdateRequestHandlerTest, TestOmitPositions, URLClassifyProcessorTest, SpellPossibilityIteratorTest, TestAtomicUpdateErrorCases, DirectUpdateHandlerTest, TestNumberUtils, BasicZkTest, TestFastOutputStream, DocumentAnalysisRequestHandlerTest, TestDefaultSimilarityFactory, FullSolrCloudDistribCmdsTest, DOMUtilTest, DebugComponentTest, AliasIntegrationTest, TestSolrJ, FileUtilsTest, TestAnalyzedSuggestions, BasicDistributedZk2Test, TestStressLucene, TestCSVLoader, SolrRequestParserTest, SuggesterTSTTest, TestReload, TestRecovery, DisMaxRequestHandlerTest, TestSolrDiscoveryProperties, CollectionsAPIDistributedZkTest, ZkNodePropsTest, StandardRequestHandlerTest, PingRequestHandlerTest, TestCollationField, UniqFieldsUpdateProcessorFactoryTest, TestIndexingPerformance, TestCodecSupport, NoCacheHeaderTest, TermVectorComponentDistributedTest, RequiredFieldsTest, SolrPluginUtilsTest, ShardRoutingCustomTest, TestStressReorder, CurrencyFieldOpenExchangeTest, DateMathParserTest, ClusterStateTest, TestElisionMultitermQuery, XmlUpdateRequestHandlerTest, CachingDirectoryFactoryTest, CopyFieldTest, DistanceFunctionTest, TestSuggestSpellingConverter, OpenCloseCoreStressTest, TestFoldingMultitermQuery, TestBinaryResponseWriter, TestFiltering, OpenExchangeRatesOrgProviderTest, TestJmxMonitoredMap, ChaosMonkeySafeLeaderTest, ShardRoutingTest, RecoveryZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.seed=2914D5C30DF344C5 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=sr_CS -Dtests.timezone=Navajo -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 0.00s J1 | RecoveryZkTest (suite) <<<
[junit4:junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=2926, name=coreLoadExecutor-2383-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:524)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
[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:746)
[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@c74417 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c47a50)
[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=2928, 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:524)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
[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@5febe5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b04889)
[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 J1 in 36.01s, 1 test, 2 errors <<< FAILURES!
[...truncated 409 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:375: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:355: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1210: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:874: There were test failures: 272 suites, 1144 tests, 2 suite-level errors, 1 error, 13 ignored (7 assumptions)
Total time: 42 minutes 10 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