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/16 05:30:33 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.6.0_41) - Build #
4728 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4728/
Java: 64bit/jdk1.6.0_41 -XX:+UseConcMarkSweepGC
2 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=1596, name=coreLoadExecutor-654-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=1596, name=coreLoadExecutor-654-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1479)
at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:34)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:744)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:872)
at org.apache.solr.core.CoreContainer.create(CoreContainer.java:955)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:579)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@374d9299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4669ed84)
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=1598, 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=1598, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1479)
at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:34)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78)
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:662)
Build Log:
[...truncated 8470 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 0 T1537 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /bad/s
[junit4:junit4] 2> 7 T1537 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-RecoveryZkTest-1363407213016
[junit4:junit4] 2> 7 T1537 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 8 T1538 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 9 T1538 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 9 T1538 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 9 T1538 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 10 T1538 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 11 T1538 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-1363407213016/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 108 T1537 oasc.ZkTestServer.run start zk server on port:52250
[junit4:junit4] 2> 108 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5f4991a0
[junit4:junit4] 2> 110 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 110 T1543 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 111 T1543 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 111 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37850
[junit4:junit4] 2> 111 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37850
[junit4:junit4] 2> 112 T1541 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 210 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0000 with negotiated timeout 10000 for client /127.0.0.1:37850
[junit4:junit4] 2> 210 T1543 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0000, negotiated timeout = 10000
[junit4:junit4] 2> 211 T1544 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f4991a0 name:ZooKeeperConnection Watcher:127.0.0.1:52250 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 211 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 212 T1537 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 218 T1542 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d716711dc0000
[junit4:junit4] 2> 219 T1544 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 219 T1537 oaz.ZooKeeper.close Session: 0x13d716711dc0000 closed
[junit4:junit4] 2> 220 T1539 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:37850 which had sessionid 0x13d716711dc0000
[junit4:junit4] 2> 220 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@31043746
[junit4:junit4] 2> 221 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 222 T1545 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 223 T1545 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 223 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37851
[junit4:junit4] 2> 223 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37851
[junit4:junit4] 2> 224 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0001 with negotiated timeout 10000 for client /127.0.0.1:37851
[junit4:junit4] 2> 224 T1545 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0001, negotiated timeout = 10000
[junit4:junit4] 2> 225 T1546 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@31043746 name:ZooKeeperConnection Watcher:127.0.0.1:52250/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 225 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 226 T1537 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 231 T1537 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 234 T1537 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 237 T1537 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 241 T1537 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> 241 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 248 T1537 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> 249 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 254 T1537 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> 255 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 258 T1537 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> 259 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 262 T1537 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> 263 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 268 T1537 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> 268 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 272 T1537 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> 273 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 278 T1537 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> 278 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 282 T1537 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> 283 T1537 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 287 T1542 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d716711dc0001
[junit4:junit4] 2> 288 T1546 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 288 T1539 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:37851 which had sessionid 0x13d716711dc0001
[junit4:junit4] 2> 288 T1537 oaz.ZooKeeper.close Session: 0x13d716711dc0001 closed
[junit4:junit4] 2> 360 T1537 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 364 T1537 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45161
[junit4:junit4] 2> 365 T1537 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 365 T1537 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 365 T1537 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298
[junit4:junit4] 2> 365 T1537 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/solr.xml
[junit4:junit4] 2> 366 T1537 oasc.CoreContainer.<init> New CoreContainer 625174472
[junit4:junit4] 2> 366 T1537 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/'
[junit4:junit4] 2> 366 T1537 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/'
[junit4:junit4] 2> 380 T1537 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 381 T1537 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 381 T1537 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 381 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 381 T1537 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 382 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 382 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 382 T1537 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 382 T1537 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 383 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 388 T1537 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 402 T1537 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52250/solr
[junit4:junit4] 2> 403 T1537 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 403 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@78f382b0
[junit4:junit4] 2> 404 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 404 T1556 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 405 T1556 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 405 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37852
[junit4:junit4] 2> 405 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37852
[junit4:junit4] 2> 406 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0002 with negotiated timeout 20000 for client /127.0.0.1:37852
[junit4:junit4] 2> 407 T1556 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0002, negotiated timeout = 20000
[junit4:junit4] 2> 407 T1557 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78f382b0 name:ZooKeeperConnection Watcher:127.0.0.1:52250 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 407 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 409 T1542 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d716711dc0002
[junit4:junit4] 2> 410 T1557 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 410 T1539 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:37852 which had sessionid 0x13d716711dc0002
[junit4:junit4] 2> 410 T1537 oaz.ZooKeeper.close Session: 0x13d716711dc0002 closed
[junit4:junit4] 2> 410 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 413 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5bf2ead1
[junit4:junit4] 2> 414 T1558 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 413 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 414 T1558 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 414 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37853
[junit4:junit4] 2> 414 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37853
[junit4:junit4] 2> 416 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0003 with negotiated timeout 20000 for client /127.0.0.1:37853
[junit4:junit4] 2> 416 T1558 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0003, negotiated timeout = 20000
[junit4:junit4] 2> 416 T1559 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bf2ead1 name:ZooKeeperConnection Watcher:127.0.0.1:52250/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 416 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 418 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 420 T1537 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 422 T1537 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45161_bad%2Fs
[junit4:junit4] 2> 423 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:45161_bad%2Fs Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:45161_bad%2Fs
[junit4:junit4] 2> 424 T1537 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45161_bad%2Fs
[junit4:junit4] 2> 429 T1537 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 438 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 439 T1537 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 442 T1537 oasc.Overseer.start Overseer (id=89352255112478723-127.0.0.1:45161_bad%2Fs-n_0000000000) starting
[junit4:junit4] 2> 443 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 445 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 446 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 447 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 449 T1561 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 450 T1537 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 454 T1537 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 457 T1537 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 461 T1560 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 465 T1562 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/collection1
[junit4:junit4] 2> 465 T1562 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 466 T1562 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 466 T1562 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 468 T1562 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/collection1/'
[junit4:junit4] 2> 469 T1562 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/collection1/lib/README' to classloader
[junit4:junit4] 2> 469 T1562 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 508 T1562 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 544 T1562 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 545 T1562 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 550 T1562 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 975 T1562 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 981 T1562 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 983 T1562 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1000 T1562 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1005 T1562 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1010 T1562 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1012 T1562 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1013 T1562 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1013 T1562 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1015 T1562 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1015 T1562 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1015 T1562 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1016 T1562 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1363407213298/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/control/data/
[junit4:junit4] 2> 1016 T1562 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c74cb02
[junit4:junit4] 2> 1017 T1562 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1018 T1562 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/control/data forceNew: false
[junit4:junit4] 2> 1018 T1562 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/control/data/index/
[junit4:junit4] 2> 1018 T1562 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1363407213016/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1019 T1562 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/control/data/index forceNew: false
[junit4:junit4] 2> 1021 T1562 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66f85196 lockFactory=org.apache.lucene.store.NativeFSLockFactory@53302afb),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1022 T1562 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1025 T1562 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1025 T1562 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1026 T1562 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1027 T1562 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1028 T1562 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1028 T1562 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1028 T1562 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1029 T1562 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1030 T1562 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1033 T1562 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1037 T1562 oass.SolrIndexSearcher.<init> Opening Searcher@d8570a9 main
[junit4:junit4] 2> 1038 T1562 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/control/data/tlog
[junit4:junit4] 2> 1039 T1562 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1039 T1562 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1044 T1563 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d8570a9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1046 T1562 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1047 T1562 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1047 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 1967 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1968 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:45161_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45161/bad/s"}
[junit4:junit4] 2> 1968 T1560 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1968 T1560 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 1969 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 1976 T1559 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> 2051 T1562 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2051 T1562 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45161/bad/s collection:control_collection shard:shard1
[junit4:junit4] 2> 2053 T1562 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2064 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:delete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2065 T1562 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2066 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2069 T1562 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2069 T1562 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2069 T1562 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:45161/bad/s/collection1/
[junit4:junit4] 2> 2070 T1562 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2070 T1562 oasc.SyncStrategy.syncToMe http://127.0.0.1:45161/bad/s/collection1/ has no replicas
[junit4:junit4] 2> 2070 T1562 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:45161/bad/s/collection1/
[junit4:junit4] 2> 2071 T1562 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2077 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3482 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3495 T1559 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> 3537 T1562 oasc.ZkController.register We are http://127.0.0.1:45161/bad/s/collection1/ and leader is http://127.0.0.1:45161/bad/s/collection1/
[junit4:junit4] 2> 3537 T1562 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45161/bad/s
[junit4:junit4] 2> 3537 T1562 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3538 T1562 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3538 T1562 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3540 T1562 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3542 T1537 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3543 T1537 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3543 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3555 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3557 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4ed4b486
[junit4:junit4] 2> 3559 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3559 T1565 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3560 T1565 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 3560 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37866
[junit4:junit4] 2> 3560 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37866
[junit4:junit4] 2> 3562 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0004 with negotiated timeout 10000 for client /127.0.0.1:37866
[junit4:junit4] 2> 3562 T1565 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0004, negotiated timeout = 10000
[junit4:junit4] 2> 3563 T1566 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ed4b486 name:ZooKeeperConnection Watcher:127.0.0.1:52250/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3563 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3565 T1537 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3568 T1537 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3639 T1537 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3642 T1537 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40375
[junit4:junit4] 2> 3643 T1537 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3643 T1537 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3644 T1537 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578
[junit4:junit4] 2> 3645 T1537 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/solr.xml
[junit4:junit4] 2> 3645 T1537 oasc.CoreContainer.<init> New CoreContainer 611219626
[junit4:junit4] 2> 3646 T1537 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/'
[junit4:junit4] 2> 3647 T1537 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/'
[junit4:junit4] 2> 3669 T1537 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3670 T1537 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3670 T1537 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3670 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3671 T1537 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3671 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3671 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3671 T1537 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3672 T1537 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3672 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3677 T1537 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3691 T1537 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52250/solr
[junit4:junit4] 2> 3691 T1537 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3692 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@49e3c29e
[junit4:junit4] 2> 3693 T1576 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3692 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3693 T1576 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 3693 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37867
[junit4:junit4] 2> 3694 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37867
[junit4:junit4] 2> 3695 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0005 with negotiated timeout 20000 for client /127.0.0.1:37867
[junit4:junit4] 2> 3695 T1576 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0005, negotiated timeout = 20000
[junit4:junit4] 2> 3695 T1577 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@49e3c29e name:ZooKeeperConnection Watcher:127.0.0.1:52250 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3696 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3697 T1542 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d716711dc0005
[junit4:junit4] 2> 3698 T1577 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3698 T1539 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:37867 which had sessionid 0x13d716711dc0005
[junit4:junit4] 2> 3698 T1537 oaz.ZooKeeper.close Session: 0x13d716711dc0005 closed
[junit4:junit4] 2> 3698 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3701 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@298259c8
[junit4:junit4] 2> 3701 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3702 T1578 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3702 T1578 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 3702 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37868
[junit4:junit4] 2> 3703 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37868
[junit4:junit4] 2> 3704 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0006 with negotiated timeout 20000 for client /127.0.0.1:37868
[junit4:junit4] 2> 3704 T1578 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0006, negotiated timeout = 20000
[junit4:junit4] 2> 3704 T1579 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@298259c8 name:ZooKeeperConnection Watcher:127.0.0.1:52250/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3705 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3706 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3707 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3709 T1537 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4713 T1537 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40375_bad%2Fs
[junit4:junit4] 2> 4714 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:40375_bad%2Fs Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:40375_bad%2Fs
[junit4:junit4] 2> 4715 T1537 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40375_bad%2Fs
[junit4:junit4] 2> 4719 T1579 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4720 T1559 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4720 T1566 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4720 T1559 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 4728 T1580 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/collection1
[junit4:junit4] 2> 4728 T1580 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4729 T1580 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4730 T1580 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4732 T1580 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/collection1/'
[junit4:junit4] 2> 4732 T1580 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/collection1/lib/README' to classloader
[junit4:junit4] 2> 4733 T1580 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4774 T1580 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 4805 T1580 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4806 T1580 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4810 T1580 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5002 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5003 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:45161_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45161/bad/s"}
[junit4:junit4] 2> 5006 T1579 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> 5006 T1566 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> 5006 T1559 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> 5161 T1580 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5171 T1580 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5173 T1580 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5187 T1580 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5190 T1580 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5194 T1580 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5195 T1580 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5195 T1580 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5195 T1580 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5196 T1580 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5196 T1580 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5196 T1580 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5197 T1580 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1363407216578/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty1/
[junit4:junit4] 2> 5197 T1580 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c74cb02
[junit4:junit4] 2> 5197 T1580 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5198 T1580 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty1 forceNew: false
[junit4:junit4] 2> 5198 T1580 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty1/index/
[junit4:junit4] 2> 5198 T1580 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5199 T1580 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty1/index forceNew: false
[junit4:junit4] 2> 5200 T1580 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e84d99c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d6a8f6d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5200 T1580 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5203 T1580 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5203 T1580 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5204 T1580 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5204 T1580 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5205 T1580 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5205 T1580 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5206 T1580 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5206 T1580 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5207 T1580 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5209 T1580 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5212 T1580 oass.SolrIndexSearcher.<init> Opening Searcher@48ad0abe main
[junit4:junit4] 2> 5212 T1580 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty1/tlog
[junit4:junit4] 2> 5213 T1580 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5213 T1580 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5219 T1581 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@48ad0abe main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5223 T1580 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5223 T1580 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6511 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6512 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40375_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40375/bad/s"}
[junit4:junit4] 2> 6512 T1560 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6513 T1560 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6520 T1559 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> 6520 T1566 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> 6520 T1579 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> 7225 T1580 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7225 T1580 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40375/bad/s collection:collection1 shard:shard1
[junit4:junit4] 2> 7227 T1580 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7239 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0006 type:delete cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7240 T1580 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7241 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7244 T1580 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7245 T1580 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7245 T1580 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40375/bad/s/collection1/
[junit4:junit4] 2> 7245 T1580 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7245 T1580 oasc.SyncStrategy.syncToMe http://127.0.0.1:40375/bad/s/collection1/ has no replicas
[junit4:junit4] 2> 7246 T1580 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40375/bad/s/collection1/
[junit4:junit4] 2> 7246 T1580 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7253 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8026 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8041 T1579 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> 8041 T1559 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> 8041 T1566 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> 8058 T1580 oasc.ZkController.register We are http://127.0.0.1:40375/bad/s/collection1/ and leader is http://127.0.0.1:40375/bad/s/collection1/
[junit4:junit4] 2> 8059 T1580 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40375/bad/s
[junit4:junit4] 2> 8059 T1580 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8059 T1580 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8060 T1580 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8062 T1580 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8064 T1537 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8064 T1537 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8065 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8135 T1537 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8139 T1537 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40333
[junit4:junit4] 2> 8140 T1537 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8140 T1537 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8141 T1537 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080
[junit4:junit4] 2> 8141 T1537 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/solr.xml
[junit4:junit4] 2> 8142 T1537 oasc.CoreContainer.<init> New CoreContainer 619296364
[junit4:junit4] 2> 8142 T1537 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/'
[junit4:junit4] 2> 8143 T1537 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/'
[junit4:junit4] 2> 8157 T1537 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8157 T1537 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8157 T1537 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8158 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8158 T1537 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8158 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8159 T1537 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8159 T1537 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8159 T1537 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8159 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8165 T1537 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8174 T1537 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52250/solr
[junit4:junit4] 2> 8175 T1537 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8175 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@767c3235
[junit4:junit4] 2> 8176 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8176 T1592 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8177 T1592 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 8177 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37870
[junit4:junit4] 2> 8177 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37870
[junit4:junit4] 2> 8178 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0007 with negotiated timeout 20000 for client /127.0.0.1:37870
[junit4:junit4] 2> 8178 T1592 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0007, negotiated timeout = 20000
[junit4:junit4] 2> 8179 T1593 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@767c3235 name:ZooKeeperConnection Watcher:127.0.0.1:52250 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8179 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8180 T1542 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d716711dc0007
[junit4:junit4] 2> 8181 T1593 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8181 T1539 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:37870 which had sessionid 0x13d716711dc0007
[junit4:junit4] 2> 8181 T1537 oaz.ZooKeeper.close Session: 0x13d716711dc0007 closed
[junit4:junit4] 2> 8182 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8184 T1537 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52250/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5f0c4faf
[junit4:junit4] 2> 8185 T1537 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8186 T1594 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:52250. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8186 T1594 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:52250, initiating session
[junit4:junit4] 2> 8186 T1539 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:37871
[junit4:junit4] 2> 8186 T1539 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:37871
[junit4:junit4] 2> 8187 T1541 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d716711dc0008 with negotiated timeout 20000 for client /127.0.0.1:37871
[junit4:junit4] 2> 8187 T1594 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:52250, sessionid = 0x13d716711dc0008, negotiated timeout = 20000
[junit4:junit4] 2> 8187 T1595 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f0c4faf name:ZooKeeperConnection Watcher:127.0.0.1:52250/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8188 T1537 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8188 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8189 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8190 T1537 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9193 T1537 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40333_bad%2Fs
[junit4:junit4] 2> 9194 T1542 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d716711dc0008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:40333_bad%2Fs Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:40333_bad%2Fs
[junit4:junit4] 2> 9195 T1537 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40333_bad%2Fs
[junit4:junit4] 2> 9199 T1566 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 9199 T1595 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9200 T1579 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9199 T1559 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9200 T1579 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> 9200 T1559 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> 9201 T1566 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9213 T1596 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/collection1
[junit4:junit4] 2> 9214 T1596 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9215 T1596 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9215 T1596 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9217 T1596 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/collection1/'
[junit4:junit4] 2> 9218 T1596 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/collection1/lib/README' to classloader
[junit4:junit4] 2> 9218 T1596 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9252 T1596 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9288 T1596 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9289 T1596 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9293 T1596 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9549 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9550 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40375_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40375/bad/s"}
[junit4:junit4] 2> 9553 T1595 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> 9553 T1579 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> 9554 T1559 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> 9554 T1566 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> 9632 T1596 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9638 T1596 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9640 T1596 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9661 T1596 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9665 T1596 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9668 T1596 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9669 T1596 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9670 T1596 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9670 T1596 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9671 T1596 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9671 T1596 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9672 T1596 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9672 T1596 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1363407221080/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/
[junit4:junit4] 2> 9673 T1596 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5c74cb02
[junit4:junit4] 2> 9673 T1596 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9674 T1596 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2 forceNew: false
[junit4:junit4] 2> 9674 T1596 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index/
[junit4:junit4] 2> 9675 T1596 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9675 T1596 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index forceNew: false
[junit4:junit4] 2> 9678 T1596 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f23987a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b22bfc2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9678 T1596 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9681 T1596 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9682 T1596 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9683 T1596 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9684 T1596 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9685 T1596 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9685 T1596 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9686 T1596 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9687 T1596 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9687 T1596 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9691 T1596 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9695 T1596 oass.SolrIndexSearcher.<init> Opening Searcher@7e9bfe9e main
[junit4:junit4] 2> 9695 T1596 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/tlog
[junit4:junit4] 2> 9696 T1596 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9696 T1596 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9703 T1597 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e9bfe9e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9707 T1596 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9707 T1596 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11059 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11060 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40333_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40333/bad/s"}
[junit4:junit4] 2> 11061 T1560 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11061 T1560 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11069 T1595 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> 11069 T1579 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> 11069 T1566 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> 11069 T1559 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> 11710 T1596 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11710 T1596 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40333/bad/s collection:collection1 shard:shard1
[junit4:junit4] 2> 11716 T1596 oasc.ZkController.register We are http://127.0.0.1:40333/bad/s/collection1/ and leader is http://127.0.0.1:40375/bad/s/collection1/
[junit4:junit4] 2> 11716 T1596 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40333/bad/s
[junit4:junit4] 2> 11716 T1596 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11717 T1596 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C68 name=collection1 org.apache.solr.core.SolrCore@2068a976 url=http://127.0.0.1:40333/bad/s/collection1 node=127.0.0.1:40333_bad%2Fs C68_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:40333_bad%2Fs, base_url=http://127.0.0.1:40333/bad/s}
[junit4:junit4] 2> 11717 T1598 C68 P40333 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11719 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11719 T1598 C68 P40333 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11719 T1598 C68 P40333 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11719 T1596 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11721 T1598 C68 P40333 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11722 T1537 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11722 T1537 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11723 T1537 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11728 T1537 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C69 name=collection1 org.apache.solr.core.SolrCore@2d9a60a3 url=http://127.0.0.1:45161/bad/s/collection1 node=127.0.0.1:45161_bad%2Fs C69_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:45161_bad%2Fs, base_url=http://127.0.0.1:45161/bad/s, leader=true}
[junit4:junit4] 2> 11746 T1552 C69 P45161 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@66f85196 lockFactory=org.apache.lucene.store.NativeFSLockFactory@53302afb),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11747 T1552 C69 P45161 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11751 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10001 (1429636094102601728)]} 0 7
[junit4:junit4] 2> 11754 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[1 (1429636094105747456)]} 0 8
[junit4:junit4] 2> ASYNC NEW_CORE C70 name=collection1 org.apache.solr.core.SolrCore@d10d2be url=http://127.0.0.1:40375/bad/s/collection1 node=127.0.0.1:40375_bad%2Fs C70_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40375_bad%2Fs, base_url=http://127.0.0.1:40375/bad/s, leader=true}
[junit4:junit4] 2> 11775 T1573 C70 P40375 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e84d99c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d6a8f6d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11776 T1573 C70 P40375 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11786 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10001 (1429636094126718976)]} 0 20
[junit4:junit4] 2> 11788 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[1 (1429636094136156160)]} 0 13
[junit4:junit4] 2> 11856 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10002 (1429636094218993664)]} 0 2
[junit4:junit4] 2> 11858 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[2 (1429636094218993665)]} 0 3
[junit4:junit4] 2> 11860 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10002 (1429636094223187968)]} 0 1
[junit4:junit4] 2> 11862 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[2 (1429636094224236544)]} 0 2
[junit4:junit4] 2> 11909 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10003 (1429636094274568192)]} 0 1
[junit4:junit4] 2> 11912 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[3 (1429636094276665344)]} 0 2
[junit4:junit4] 2> 11914 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10003 (1429636094279811072)]} 0 2
[junit4:junit4] 2> 11916 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[3 (1429636094281908224)]} 0 1
[junit4:junit4] 2> 11947 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10004 (1429636094314414080)]} 0 1
[junit4:junit4] 2> 11950 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[4 (1429636094317559808)]} 0 2
[junit4:junit4] 2> 11952 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10004 (1429636094319656960)]} 0 1
[junit4:junit4] 2> 11955 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[4 (1429636094321754112)]} 0 2
[junit4:junit4] 2> 12027 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10005 (1429636094398300160)]} 0 1
[junit4:junit4] 2> 12030 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[5 (1429636094401445888)]} 0 2
[junit4:junit4] 2> 12032 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10005 (1429636094403543040)]} 0 2
[junit4:junit4] 2> 12035 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[5 (1429636094405640192)]} 0 2
[junit4:junit4] 2> 12119 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10006 (1429636094493720576)]} 0 2
[junit4:junit4] 2> 12121 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[6 (1429636094496866304)]} 0 1
[junit4:junit4] 2> 12123 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10006 (1429636094498963456)]} 0 1
[junit4:junit4] 2> 12126 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[6 (1429636094502109184)]} 0 2
[junit4:junit4] 2> 12157 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10007 (1429636094533566464)]} 0 2
[junit4:junit4] 2> 12160 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[7 (1429636094536712192)]} 0 2
[junit4:junit4] 2> 12161 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10007 (1429636094538809344)]} 0 1
[junit4:junit4] 2> 12164 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[7 (1429636094541955072)]} 0 1
[junit4:junit4] 2> 12239 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10008 (1429636094619549696)]} 0 2
[junit4:junit4] 2> 12242 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[8 (1429636094623744000)]} 0 2
[junit4:junit4] 2> 12243 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10008 (1429636094624792576)]} 0 1
[junit4:junit4] 2> 12247 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[8 (1429636094627938304)]} 0 2
[junit4:junit4] 2> 12285 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10005 (-1429636094668832768)]} 0 2
[junit4:junit4] 2> 12288 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[5 (-1429636094671978496)]} 0 1
[junit4:junit4] 2> 12288 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10005 (-1429636094673027072)]} 0 0
[junit4:junit4] 2> 12292 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[5 (-1429636094676172800)]} 0 1
[junit4:junit4] 2> 12294 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10009 (1429636094677221376)]} 0 2
[junit4:junit4] 2> 12297 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[9 (1429636094680367104)]} 0 2
[junit4:junit4] 2> 12299 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10009 (1429636094682464256)]} 0 2
[junit4:junit4] 2> 12302 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[9 (1429636094685609984)]} 0 2
[junit4:junit4] 2> 12303 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10009 (-1429636094687707136)]} 0 1
[junit4:junit4] 2> 12306 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[9 (-1429636094691901440)]} 0 1
[junit4:junit4] 2> 12307 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10009 (-1429636094692950016)]} 0 1
[junit4:junit4] 2> 12311 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[9 (-1429636094697144320)]} 0 1
[junit4:junit4] 2> 12312 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10010 (1429636094697144320)]} 0 2
[junit4:junit4] 2> 12315 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10 (1429636094700290048)]} 0 1
[junit4:junit4] 2> 12317 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10010 (1429636094701338624)]} 0 2
[junit4:junit4] 2> 12321 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10 (1429636094706581504)]} 0 3
[junit4:junit4] 2> 12322 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10011 (1429636094707630080)]} 0 2
[junit4:junit4] 2> 12326 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[11 (1429636094711824384)]} 0 2
[junit4:junit4] 2> 12327 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10011 (1429636094711824384)]} 0 2
[junit4:junit4] 2> 12330 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[11 (1429636094716018688)]} 0 1
[junit4:junit4] 2> 12370 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10010 (-1429636094759010304)]} 0 1
[junit4:junit4] 2> 12373 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10 (-1429636094762156032)]} 0 0
[junit4:junit4] 2> 12373 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10010 (-1429636094762156032)]} 0 0
[junit4:junit4] 2> 12376 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10 (-1429636094765301760)]} 0 1
[junit4:junit4] 2> 12378 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10012 (1429636094765301760)]} 0 2
[junit4:junit4] 2> 12381 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[12 (1429636094768447488)]} 0 2
[junit4:junit4] 2> 12382 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10012 (1429636094770544640)]} 0 1
[junit4:junit4] 2> 12384 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[12 (1429636094773690368)]} 0 1
[junit4:junit4] 2> 12482 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10013 (1429636094874353664)]} 0 2
[junit4:junit4] 2> 12483 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[13 (1429636094876450816)]} 0 1
[junit4:junit4] 2> 12486 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10013 (1429636094879596544)]} 0 1
[junit4:junit4] 2> 12488 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[13 (1429636094881693696)]} 0 2
[junit4:junit4] 2> 12504 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10014 (1429636094897422336)]} 0 2
[junit4:junit4] 2> 12506 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[14 (1429636094899519488)]} 0 2
[junit4:junit4] 2> 12508 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10014 (1429636094902665216)]} 0 2
[junit4:junit4] 2> 12510 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[14 (1429636094904762368)]} 0 1
[junit4:junit4] 2> 12543 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10011 (-1429636094940413952)]} 0 1
[junit4:junit4] 2> 12546 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[11 (-1429636094942511104)]} 0 1
[junit4:junit4] 2> 12547 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10011 (-1429636094944608256)]} 0 1
[junit4:junit4] 2> 12550 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[11 (-1429636094947753984)]} 0 1
[junit4:junit4] 2> 12552 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10015 (1429636094947753984)]} 0 2
[junit4:junit4] 2> 12555 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[15 (1429636094950899712)]} 0 2
[junit4:junit4] 2> 12556 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10015 (1429636094952996864)]} 0 1
[junit4:junit4] 2> 12559 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[15 (1429636094956142592)]} 0 1
[junit4:junit4] 2> 12562 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10016 (1429636094959288320)]} 0 1
[junit4:junit4] 2> 12565 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[16 (1429636094962434048)]} 0 1
[junit4:junit4] 2> 12567 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10016 (1429636094964531200)]} 0 2
[junit4:junit4] 2> 12570 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[16 (1429636094967676928)]} 0 1
[junit4:junit4] 2> 12576 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12577 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40333_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40333/bad/s"}
[junit4:junit4] 2> 12584 T1595 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> 12584 T1559 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> 12584 T1566 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> 12584 T1579 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> 12654 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10015 (-1429636095056805888)]} 0 1
[junit4:junit4] 2> 12657 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[15 (-1429636095059951616)]} 0 0
[junit4:junit4] 2> C68_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:40333_bad%2Fs, base_url=http://127.0.0.1:40333/bad/s}
[junit4:junit4] 2> 12670 T1590 C68 P40333 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f23987a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b22bfc2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12672 T1590 C68 P40333 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12674 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10015 (-1429636095061000192)]} 0 5
[junit4:junit4] 2> 12674 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[15 (-1429636095064145920)]} 0 4
[junit4:junit4] 2> 12675 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[15 (-1429636095064145920)]} 0 14
[junit4:junit4] 2> 12675 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10015 (-1429636095061000192)]} 0 17
[junit4:junit4] 2> 12680 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[17 (1429636095083020288)]} 0 1
[junit4:junit4] 2> 12681 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10017 (1429636095083020289)]} 0 2
[junit4:junit4] 2> 12690 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1429636095088263168)]} 0 3
[junit4:junit4] 2> 12691 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[17 (1429636095088263168)]} 0 8
[junit4:junit4] 2> 12692 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10017 (1429636095089311744)]} 0 3
[junit4:junit4] 2> 12693 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10017 (1429636095089311744)]} 0 9
[junit4:junit4] 2> 12728 T1575 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=3&state=recovering&nodeName=127.0.0.1:40333_bad%252Fs&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 12768 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[18 (1429636095175294976)]} 0 1
[junit4:junit4] 2> 12770 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10018 (1429636095176343552)]} 0 2
[junit4:junit4] 2> 12777 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1429636095180537856)]} 0 2
[junit4:junit4] 2> 12778 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[18 (1429636095180537856)]} 0 7
[junit4:junit4] 2> 12779 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1429636095181586432)]} 0 2
[junit4:junit4] 2> 12780 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10018 (1429636095181586432)]} 0 7
[junit4:junit4] 2> 12796 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[16 (-1429636095205703680)]} 0 1
[junit4:junit4] 2> 12798 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10016 (-1429636095207800832)]} 0 1
[junit4:junit4] 2> 12803 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[16 (-1429636095209897984)]} 0 0
[junit4:junit4] 2> 12804 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10016 (-1429636095210946560)]} 0 1
[junit4:junit4] 2> 12804 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[16 (-1429636095209897984)]} 0 4
[junit4:junit4] 2> 12805 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10016 (-1429636095210946560)]} 0 4
[junit4:junit4] 2> 12809 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[19 (1429636095217238016)]} 0 2
[junit4:junit4] 2> 12810 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10019 (1429636095218286592)]} 0 2
[junit4:junit4] 2> 12817 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1429636095222480896)]} 0 2
[junit4:junit4] 2> 12818 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[19 (1429636095222480896)]} 0 7
[junit4:junit4] 2> 12819 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1429636095223529472)]} 0 2
[junit4:junit4] 2> 12820 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10019 (1429636095223529472)]} 0 7
[junit4:junit4] 2> 12875 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[17 (-1429636095288541184)]} 0 0
[junit4:junit4] 2> 12877 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10017 (-1429636095290638336)]} 0 1
[junit4:junit4] 2> 12881 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[17 (-1429636095291686912)]} 0 0
[junit4:junit4] 2> 12882 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[17 (-1429636095291686912)]} 0 4
[junit4:junit4] 2> 12883 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10017 (-1429636095293784064)]} 0 0
[junit4:junit4] 2> 12884 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10017 (-1429636095293784064)]} 0 4
[junit4:junit4] 2> 12887 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[20 (1429636095300075520)]} 0 2
[junit4:junit4] 2> 12889 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10020 (1429636095301124096)]} 0 2
[junit4:junit4] 2> 12896 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1429636095305318400)]} 0 2
[junit4:junit4] 2> 12903 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[20 (1429636095305318400)]} 0 13
[junit4:junit4] 2> 12905 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1429636095306366976)]} 0 3
[junit4:junit4] 2> 12906 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10020 (1429636095306366976)]} 0 14
[junit4:junit4] 2> 12927 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[21 (1429636095342018560)]} 0 2
[junit4:junit4] 2> 12930 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10021 (1429636095344115712)]} 0 2
[junit4:junit4] 2> 12935 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1429636095346212864)]} 0 2
[junit4:junit4] 2> 12936 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[21 (1429636095346212864)]} 0 6
[junit4:junit4] 2> 12937 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1429636095349358592)]} 0 1
[junit4:junit4] 2> 12938 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10021 (1429636095349358592)]} 0 6
[junit4:junit4] 2> 13034 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[22 (1429636095454216192)]} 0 1
[junit4:junit4] 2> 13037 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10022 (1429636095457361920)]} 0 2
[junit4:junit4] 2> 13042 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1429636095458410496)]} 0 1
[junit4:junit4] 2> 13043 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[22 (1429636095458410496)]} 0 6
[junit4:junit4] 2> 13046 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1429636095462604800)]} 0 2
[junit4:junit4] 2> 13047 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10022 (1429636095462604800)]} 0 7
[junit4:junit4] 2> 13060 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[19 (-1429636095482527744)]} 0 1
[junit4:junit4] 2> 13064 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10019 (-1429636095485673472)]} 0 1
[junit4:junit4] 2> 13069 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[19 (-1429636095486722048)]} 0 2
[junit4:junit4] 2> 13070 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[19 (-1429636095486722048)]} 0 6
[junit4:junit4] 2> 13071 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10019 (-1429636095491964928)]} 0 0
[junit4:junit4] 2> 13072 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10019 (-1429636095491964928)]} 0 5
[junit4:junit4] 2> 13074 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[23 (1429636095496159232)]} 0 1
[junit4:junit4] 2> 13077 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10023 (1429636095498256384)]} 0 2
[junit4:junit4] 2> 13082 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1429636095501402112)]} 0 1
[junit4:junit4] 2> 13083 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[23 (1429636095501402112)]} 0 6
[junit4:junit4] 2> 13085 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1429636095503499264)]} 0 2
[junit4:junit4] 2> 13086 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10023 (1429636095503499264)]} 0 6
[junit4:junit4] 2> 13127 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[21 (-1429636095552782336)]} 0 1
[junit4:junit4] 2> 13129 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10021 (-1429636095554879488)]} 0 0
[junit4:junit4] 2> 13133 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[21 (-1429636095555928064)]} 0 1
[junit4:junit4] 2> 13134 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[21 (-1429636095555928064)]} 0 4
[junit4:junit4] 2> 13135 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10021 (-1429636095559073792)]} 0 0
[junit4:junit4] 2> 13137 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10021 (-1429636095559073792)]} 0 5
[junit4:junit4] 2> 13139 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[24 (1429636095563268096)]} 0 2
[junit4:junit4] 2> 13141 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10024 (1429636095566413824)]} 0 1
[junit4:junit4] 2> 13147 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1429636095568510976)]} 0 2
[junit4:junit4] 2> 13148 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[24 (1429636095568510976)]} 0 6
[junit4:junit4] 2> 13150 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1429636095570608128)]} 0 2
[junit4:junit4] 2> 13151 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10024 (1429636095570608128)]} 0 7
[junit4:junit4] 2> 13218 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[22 (-1429636095648202752)]} 0 0
[junit4:junit4] 2> 13221 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10022 (-1429636095651348480)]} 0 1
[junit4:junit4] 2> 13224 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[22 (-1429636095651348480)]} 0 0
[junit4:junit4] 2> 13225 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[22 (-1429636095651348480)]} 0 4
[junit4:junit4] 2> 13227 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10022 (-1429636095654494208)]} 0 1
[junit4:junit4] 2> 13228 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10022 (-1429636095654494208)]} 0 4
[junit4:junit4] 2> 13230 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[25 (1429636095659737088)]} 0 2
[junit4:junit4] 2> 13233 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10025 (1429636095661834240)]} 0 2
[junit4:junit4] 2> 13238 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1429636095663931392)]} 0 1
[junit4:junit4] 2> 13239 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[25 (1429636095663931392)]} 0 6
[junit4:junit4] 2> 13242 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1429636095667077120)]} 0 2
[junit4:junit4] 2> 13242 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10025 (1429636095667077120)]} 0 6
[junit4:junit4] 2> 13331 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[25 (-1429636095766691840)]} 0 0
[junit4:junit4] 2> 13334 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10025 (-1429636095768788992)]} 0 1
[junit4:junit4] 2> 13337 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[25 (-1429636095770886144)]} 0 0
[junit4:junit4] 2> 13338 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[25 (-1429636095770886144)]} 0 4
[junit4:junit4] 2> 13339 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10025 (-1429636095772983296)]} 0 0
[junit4:junit4] 2> 13340 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10025 (-1429636095772983296)]} 0 4
[junit4:junit4] 2> 13342 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[26 (1429636095777177600)]} 0 1
[junit4:junit4] 2> 13344 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10026 (1429636095779274752)]} 0 1
[junit4:junit4] 2> 13350 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1429636095781371904)]} 0 1
[junit4:junit4] 2> 13352 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[26 (1429636095781371904)]} 0 7
[junit4:junit4] 2> 13352 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1429636095783469056)]} 0 1
[junit4:junit4] 2> 13353 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10026 (1429636095783469056)]} 0 6
[junit4:junit4] 2> 13454 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[27 (1429636095894618112)]} 0 1
[junit4:junit4] 2> 13456 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10027 (1429636095896715264)]} 0 1
[junit4:junit4] 2> 13463 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1429636095899860992)]} 0 2
[junit4:junit4] 2> 13464 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[27 (1429636095899860992)]} 0 7
[junit4:junit4] 2> 13464 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1429636095900909568)]} 0 1
[junit4:junit4] 2> 13465 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10027 (1429636095900909568)]} 0 6
[junit4:junit4] 2> 13507 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[27 (-1429636095951241216)]} 0 0
[junit4:junit4] 2> 13509 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10027 (-1429636095953338368)]} 0 0
[junit4:junit4] 2> 13513 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[27 (-1429636095954386944)]} 0 0
[junit4:junit4] 2> 13514 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[27 (-1429636095954386944)]} 0 4
[junit4:junit4] 2> 13515 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10027 (-1429636095956484096)]} 0 0
[junit4:junit4] 2> 13516 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[10027 (-1429636095956484096)]} 0 4
[junit4:junit4] 2> 13518 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[28 (1429636095961726976)]} 0 1
[junit4:junit4] 2> 13521 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10028 (1429636095963824128)]} 0 2
[junit4:junit4] 2> 13527 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1429636095966969856)]} 0 2
[junit4:junit4] 2> 13528 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[28 (1429636095966969856)]} 0 7
[junit4:junit4] 2> 13529 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1429636095969067008)]} 0 2
[junit4:junit4] 2> 13530 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10028 (1429636095969067008)]} 0 6
[junit4:junit4] 2> 13599 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[29 (1429636096046661632)]} 0 1
[junit4:junit4] 2> 13602 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10029 (1429636096048758784)]} 0 2
[junit4:junit4] 2> 13608 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1429636096051904512)]} 0 2
[junit4:junit4] 2> 13609 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[29 (1429636096051904512)]} 0 7
[junit4:junit4] 2> 13610 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1429636096054001664)]} 0 1
[junit4:junit4] 2> 13611 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10029 (1429636096054001664)]} 0 6
[junit4:junit4] 2> 13644 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[30 (1429636096093847552)]} 0 1
[junit4:junit4] 2> 13647 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10030 (1429636096095944704)]} 0 2
[junit4:junit4] 2> 13652 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1429636096099090432)]} 0 1
[junit4:junit4] 2> 13653 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[30 (1429636096099090432)]} 0 6
[junit4:junit4] 2> 13655 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1429636096101187584)]} 0 1
[junit4:junit4] 2> 13656 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10030 (1429636096101187584)]} 0 6
[junit4:junit4] 2> 13673 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[30 (-1429636096125304832)]} 0 0
[junit4:junit4] 2> 13676 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10030 (-1429636096127401984)]} 0 1
[junit4:junit4] 2> 13679 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[30 (-1429636096128450560)]} 0 0
[junit4:junit4] 2> 13680 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[30 (-1429636096128450560)]} 0 4
[junit4:junit4] 2> 13682 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10030 (-1429636096131596288)]} 0 1
[junit4:junit4] 2> 13683 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[10030 (-1429636096131596288)]} 0 4
[junit4:junit4] 2> 13685 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[31 (1429636096135790592)]} 0 2
[junit4:junit4] 2> 13687 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10031 (1429636096138936320)]} 0 1
[junit4:junit4] 2> 13693 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1429636096141033472)]} 0 2
[junit4:junit4] 2> 13694 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[31 (1429636096141033472)]} 0 6
[junit4:junit4] 2> 13696 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1429636096144179200)]} 0 2
[junit4:junit4] 2> 13697 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10031 (1429636096144179200)]} 0 7
[junit4:junit4] 2> 13732 T1537 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40333
[junit4:junit4] 2> 13733 T1537 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=619296364
[junit4:junit4] 2> 13759 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[32 (1429636096214433792)]} 0 2
[junit4:junit4] 2> 13761 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10032 (1429636096216530944)]} 0 1
[junit4:junit4] 2> 13767 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1429636096219676672)]} 0 1
[junit4:junit4] 2> 13769 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[32 (1429636096219676672)]} 0 7
[junit4:junit4] 2> 13770 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10032 (1429636096221773824)]} 0 2
[junit4:junit4] 2> 13771 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10032 (1429636096221773824)]} 0 7
[junit4:junit4] 2> 13868 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[33 (1429636096327680000)]} 0 2
[junit4:junit4] 2> 13870 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10033 (1429636096329777152)]} 0 2
[junit4:junit4] 2> 13876 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1429636096332922880)]} 0 2
[junit4:junit4] 2> 13877 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[33 (1429636096332922880)]} 0 6
[junit4:junit4] 2> 13878 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10033 (1429636096335020032)]} 0 2
[junit4:junit4] 2> 13879 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10033 (1429636096335020032)]} 0 6
[junit4:junit4] 2> 13924 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[34 (1429636096387448832)]} 0 2
[junit4:junit4] 2> 13926 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10034 (1429636096388497408)]} 0 2
[junit4:junit4] 2> 13932 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1429636096391643136)]} 0 2
[junit4:junit4] 2> 13933 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[34 (1429636096391643136)]} 0 6
[junit4:junit4] 2> 13934 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10034 (1429636096393740288)]} 0 2
[junit4:junit4] 2> 13935 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10034 (1429636096393740288)]} 0 6
[junit4:junit4] 2> 14009 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[35 (1429636096476577792)]} 0 1
[junit4:junit4] 2> 14011 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10035 (1429636096478674944)]} 0 2
[junit4:junit4] 2> 14017 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1429636096480772096)]} 0 1
[junit4:junit4] 2> 14018 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[35 (1429636096480772096)]} 0 6
[junit4:junit4] 2> 14019 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10035 (1429636096482869248)]} 0 1
[junit4:junit4] 2> 14020 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10035 (1429636096482869248)]} 0 6
[junit4:junit4] 2> 14037 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[36 (1429636096505937920)]} 0 1
[junit4:junit4] 2> 14039 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10036 (1429636096508035072)]} 0 2
[junit4:junit4] 2> 14044 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1429636096510132224)]} 0 1
[junit4:junit4] 2> 14045 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[36 (1429636096510132224)]} 0 5
[junit4:junit4] 2> 14046 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10036 (1429636096512229376)]} 0 1
[junit4:junit4] 2> 14047 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10036 (1429636096512229376)]} 0 5
[junit4:junit4] 2> 14091 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14092 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40333_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40333/bad/s"}
[junit4:junit4] 2> 14093 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[37 (1429636096564658176)]} 0 1
[junit4:junit4] 2> 14096 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10037 (1429636096566755328)]} 0 2
[junit4:junit4] 2> 14100 T1595 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> 14100 T1566 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> 14100 T1579 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> 14100 T1559 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> C68_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:40333_bad%2Fs, base_url=http://127.0.0.1:40333/bad/s}
[junit4:junit4] 2> 14103 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1429636096569901056)]} 0 2
[junit4:junit4] 2> 14104 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[37 (1429636096569901056)]} 0 8
[junit4:junit4] 2> 14105 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10037 (1429636096571998208)]} 0 2
[junit4:junit4] 2> 14106 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10037 (1429636096571998208)]} 0 7
[junit4:junit4] 2> 14197 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[38 (1429636096673710080)]} 0 2
[junit4:junit4] 2> 14199 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10038 (1429636096674758656)]} 0 2
[junit4:junit4] 2> 14201 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[38 (1429636096677904384)]} 0 1
[junit4:junit4] 2> 14203 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10038 (1429636096680001536)]} 0 1
[junit4:junit4] 2> 14281 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[39 (1429636096761790464)]} 0 2
[junit4:junit4] 2> 14283 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10039 (1429636096762839040)]} 0 2
[junit4:junit4] 2> 14285 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[39 (1429636096765984768)]} 0 1
[junit4:junit4] 2> 14287 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10039 (1429636096768081920)]} 0 1
[junit4:junit4] 2> 14309 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[32 (-1429636096791150592)]} 0 1
[junit4:junit4] 2> 14311 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10032 (-1429636096794296320)]} 0 1
[junit4:junit4] 2> 14312 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[32 (-1429636096795344896)]} 0 1
[junit4:junit4] 2> 14314 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[10032 (-1429636096797442048)]} 0 0
[junit4:junit4] 2> 14316 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[40 (1429636096798490624)]} 0 1
[junit4:junit4] 2> 14319 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10040 (1429636096800587776)]} 0 2
[junit4:junit4] 2> 14320 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[40 (1429636096802684928)]} 0 1
[junit4:junit4] 2> 14323 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10040 (1429636096805830656)]} 0 1
[junit4:junit4] 2> 14379 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[41 (1429636096864550912)]} 0 1
[junit4:junit4] 2> 14382 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10041 (1429636096866648064)]} 0 2
[junit4:junit4] 2> 14384 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[41 (1429636096869793792)]} 0 2
[junit4:junit4] 2> 14387 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10041 (1429636096871890944)]} 0 2
[junit4:junit4] 2> 14467 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[42 (1429636096956825600)]} 0 1
[junit4:junit4] 2> 14471 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10042 (1429636096959971328)]} 0 2
[junit4:junit4] 2> 14472 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[42 (1429636096962068480)]} 0 2
[junit4:junit4] 2> 14475 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10042 (1429636096965214208)]} 0 1
[junit4:junit4] 2> 14556 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[43 (1429636097050148864)]} 0 2
[junit4:junit4] 2> 14565 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10043 (1429636097058537472)]} 0 2
[junit4:junit4] 2> 14567 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[43 (1429636097060634624)]} 0 2
[junit4:junit4] 2> 14570 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10043 (1429636097063780352)]} 0 2
[junit4:junit4] 2> 14611 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[44 (1429636097107820544)]} 0 1
[junit4:junit4] 2> 14614 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10044 (1429636097110966272)]} 0 1
[junit4:junit4] 2> 14616 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[44 (1429636097113063424)]} 0 2
[junit4:junit4] 2> 14619 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10044 (1429636097115160576)]} 0 2
[junit4:junit4] 2> 14713 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[33 (-1429636097215823872)]} 0 0
[junit4:junit4] 2> 14716 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10033 (-1429636097218969600)]} 0 0
[junit4:junit4] 2> 14717 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[33 (-1429636097220018176)]} 0 1
[junit4:junit4] 2> 14719 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10033 (-1429636097222115328)]} 0 0
[junit4:junit4] 2> 14721 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[45 (1429636097223163904)]} 0 1
[junit4:junit4] 2> 14724 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10045 (1429636097226309632)]} 0 2
[junit4:junit4] 2> 14726 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[45 (1429636097228406784)]} 0 2
[junit4:junit4] 2> 14729 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10045 (1429636097230503936)]} 0 1
[junit4:junit4] 2> 14729 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:40375/bad/s/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 14730 T1598 C68 P40333 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40333/bad/s START replicas=[http://127.0.0.1:40375/bad/s/collection1/] nUpdates=100
[junit4:junit4] 2> 14740 T1598 C68 P40333 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 14740 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 14740 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 14741 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 14741 T1598 C68 P40333 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/tlog/tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 14741 T1572 C70 P40375 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=8
[junit4:junit4] 2> 14741 T1598 C68 P40333 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:40375/bad/s/collection1/. core=collection1
[junit4:junit4] 2> 14742 T1598 C68 P40333 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14747 T1573 C70 P40375 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14759 T1573 C70 P40375 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e84d99c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d6a8f6d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7e84d99c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d6a8f6d),segFN=segments_2,generation=2,filenames=[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 14759 T1573 C70 P40375 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 14760 T1573 C70 P40375 oass.SolrIndexSearcher.<init> Opening Searcher@605be4bb realtime
[junit4:junit4] 2> 14761 T1573 C70 P40375 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 14761 T1573 C70 P40375 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 14762 T1598 C68 P40333 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14762 T1598 C68 P40333 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 14764 T1574 C70 P40375 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14764 T1574 C70 P40375 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 14764 T1598 C68 P40333 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 14765 T1598 C68 P40333 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 14765 T1598 C68 P40333 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 14767 T1572 C70 P40375 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 14768 T1598 C68 P40333 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 14
[junit4:junit4] 2> 14769 T1598 C68 P40333 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index.20130316081347777 forceNew: false
[junit4:junit4] 2> 14769 T1598 C68 P40333 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78) fullCopy=true
[junit4:junit4] 2> 14771 T1573 C70 P40375 REQ /replication {file=_0.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14774 T1575 C70 P40375 REQ /replication {file=_0_Lucene42_0.dvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14774 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[39 (-1429636097279787008)]} 0 0
[junit4:junit4] 2> 14777 T1574 C70 P40375 REQ /replication {file=_0_Lucene41_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14777 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10039 (-1429636097282932736)]} 0 1
[junit4:junit4] 2> 14777 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[39 (-1429636097282932736)]} 0 0
[junit4:junit4] 2> 14779 T1575 C70 P40375 REQ /replication {file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14780 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10039 (-1429636097286078464)]} 0 1
[junit4:junit4] 2> 14781 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[46 (1429636097286078464)]} 0 2
[junit4:junit4] 2> 14784 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10046 (1429636097289224192)]} 0 1
[junit4:junit4] 2> 14785 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[46 (1429636097289224192)]} 0 2
[junit4:junit4] 2> 14785 T1574 C70 P40375 REQ /replication {file=_0_Lucene42_0.dvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14795 T1575 C70 P40375 REQ /replication {file=_0.nvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14795 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10046 (1429636097300758528)]} 0 1
[junit4:junit4] 2> 14798 T1572 C70 P40375 REQ /replication {file=_0_Lucene41_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14801 T1574 C70 P40375 REQ /replication {file=_0.nvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14804 T1573 C70 P40375 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14807 T1575 C70 P40375 REQ /replication {file=_0.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14810 T1572 C70 P40375 REQ /replication {file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14813 T1574 C70 P40375 REQ /replication {file=_0_Lucene41_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14816 T1573 C70 P40375 REQ /replication {file=_0_Lucene41_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14823 T1575 C70 P40375 REQ /replication {file=_0.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14824 T1598 C68 P40333 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 14825 T1598 C68 P40333 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130316081347777
[junit4:junit4] 2> 14826 T1598 C68 P40333 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 14826 T1598 C68 P40333 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 14826 T1598 C68 P40333 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 14829 T1598 C68 P40333 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index/ new=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index.20130316081347777
[junit4:junit4] 2> 14831 T1598 C68 P40333 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78),segFN=segments_2,generation=2,filenames=[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4:junit4] 2> 14831 T1598 C68 P40333 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4:junit4] 2> 14832 T1598 C68 P40333 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 14834 T1598 C68 P40333 oass.SolrIndexSearcher.<init> Opening Searcher@436774a2 main
[junit4:junit4] 2> 14836 T1597 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@436774a2 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C90/30)}
[junit4:junit4] 2> 14837 T1598 C68 P40333 oash.SnapPuller$2.preClose removing old index files MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f23987a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b22bfc2)
[junit4:junit4] 2> 14837 T1598 C68 P40333 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/index
[junit4:junit4] 2> 14838 T1598 C68 P40333 oash.SnapPuller$2.postClose removing old index directory MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f23987a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b22bfc2)
[junit4:junit4] 2> 14842 T1598 C68 P40333 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 14842 T1606 C68 P40333 oasu.UpdateLog$LogReplayer.doReplay WARNING Starting log replay tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1363407213016/jetty2/tlog/tlog.0000000000000000000 refcount=2} active=true starting pos=6048
[junit4:junit4] 2> 14843 T1606 C68 P40333 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14852 T1606 C68 P40333 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78),segFN=segments_2,generation=2,filenames=[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, segments_2, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _0.fdt]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78),segFN=segments_3,generation=3,filenames=[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, segments_3, _0.fdt]
[junit4:junit4] 2> 14852 T1606 C68 P40333 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, segments_3, _0.fdt]
[junit4:junit4] 2> 14853 T1606 C68 P40333 oass.SolrIndexSearcher.<init> Opening Searcher@1472f0f9 main
[junit4:junit4] 2> 14853 T1606 C68 P40333 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 14854 T1597 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1472f0f9 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C90/30)}
[junit4:junit4] 2> 14854 T1606 C68 P40333 oasu.UpdateLog$LogReplayer.run WARNING Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=6048}
[junit4:junit4] 2> 14854 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 14855 T1598 C68 P40333 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 14855 T1598 C68 P40333 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14856 T1598 C68 P40333 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 14878 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[47 (1429636097387790336)]} 0 2
[junit4:junit4] 2> 14882 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[47 (1429636097391984640)]} 0 1
[junit4:junit4] 2> 14888 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10047 (1429636097398276096)]} 0 1
[junit4:junit4] 2> 14891 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10047 (1429636097401421824)]} 0 1
[junit4:junit4] 2> 14949 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[40 (-1429636097463287808)]} 0 0
[junit4:junit4] 2> 14952 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[40 (-1429636097466433536)]} 0 1
[junit4:junit4] 2> 14955 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[48 (1429636097468530688)]} 0 1
[junit4:junit4] 2> 14957 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10040 (-1429636097471676416)]} 0 0
[junit4:junit4] 2> 14958 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[48 (1429636097471676416)]} 0 1
[junit4:junit4] 2> 14960 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10040 (-1429636097474822144)]} 0 0
[junit4:junit4] 2> 14963 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10048 (1429636097477967872)]} 0 0
[junit4:junit4] 2> 14967 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10048 (1429636097481113600)]} 0 1
[junit4:junit4] 2> 15036 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[49 (1429636097553465344)]} 0 2
[junit4:junit4] 2> 15040 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[49 (1429636097557659648)]} 0 1
[junit4:junit4] 2> 15043 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10049 (1429636097561853952)]} 0 1
[junit4:junit4] 2> 15047 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10049 (1429636097564999680)]} 0 1
[junit4:junit4] 2> 15121 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[50 (1429636097643642880)]} 0 1
[junit4:junit4] 2> 15125 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[50 (1429636097646788608)]} 0 1
[junit4:junit4] 2> 15127 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10050 (1429636097648885760)]} 0 1
[junit4:junit4] 2> 15130 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10050 (1429636097652031488)]} 0 1
[junit4:junit4] 2> 15175 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[42 (-1429636097700265984)]} 0 0
[junit4:junit4] 2> 15177 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[42 (-1429636097702363136)]} 0 0
[junit4:junit4] 2> 15179 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10042 (-1429636097704460288)]} 0 0
[junit4:junit4] 2> 15180 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[51 (1429636097705508864)]} 0 1
[junit4:junit4] 2> 15182 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10042 (-1429636097707606016)]} 0 1
[junit4:junit4] 2> 15183 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[51 (1429636097708654592)]} 0 0
[junit4:junit4] 2> 15184 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10051 (1429636097709703168)]} 0 0
[junit4:junit4] 2> 15187 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10051 (1429636097712848896)]} 0 0
[junit4:junit4] 2> 15285 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[47 (-1429636097814560768)]} 0 1
[junit4:junit4] 2> 15287 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[47 (-1429636097817706496)]} 0 0
[junit4:junit4] 2> 15288 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10047 (-1429636097818755072)]} 0 1
[junit4:junit4] 2> 15290 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10047 (-1429636097820852224)]} 0 0
[junit4:junit4] 2> 15291 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[52 (1429636097820852224)]} 0 1
[junit4:junit4] 2> 15293 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10052 (1429636097822949376)]} 0 1
[junit4:junit4] 2> 15294 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[52 (1429636097823997952)]} 0 1
[junit4:junit4] 2> 15296 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10052 (1429636097826095104)]} 0 1
[junit4:junit4] 2> 15362 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[48 (-1429636097896349696)]} 0 0
[junit4:junit4] 2> 15363 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10048 (-1429636097897398272)]} 0 0
[junit4:junit4] 2> 15365 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[48 (-1429636097899495424)]} 0 1
[junit4:junit4] 2> 15365 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10048 (-1429636097899495425)]} 0 0
[junit4:junit4] 2> 15368 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[53 (1429636097901592576)]} 0 1
[junit4:junit4] 2> 15368 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10053 (1429636097902641152)]} 0 0
[junit4:junit4] 2> 15371 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[53 (1429636097904738304)]} 0 1
[junit4:junit4] 2> 15372 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10053 (1429636097904738305)]} 0 2
[junit4:junit4] 2> 15465 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[54 (1429636098003304448)]} 0 1
[junit4:junit4] 2> 15465 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10054 (1429636098003304449)]} 0 1
[junit4:junit4] 2> 15468 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[54 (1429636098006450176)]} 0 1
[junit4:junit4] 2> 15469 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10054 (1429636098007498752)]} 0 1
[junit4:junit4] 2> 15472 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[49 (-1429636098011693056)]} 0 1
[junit4:junit4] 2> 15472 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10049 (-1429636098011693057)]} 0 0
[junit4:junit4] 2> 15475 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[49 (-1429636098013790208)]} 0 0
[junit4:junit4] 2> 15474 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10049 (-1429636098013790209)]} 0 0
[junit4:junit4] 2> 15478 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10055 (1429636098016935936)]} 0 1
[junit4:junit4] 2> 15478 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[55 (1429636098016935937)]} 0 1
[junit4:junit4] 2> 15481 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10055 (1429636098020081664)]} 0 1
[junit4:junit4] 2> 15482 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[55 (1429636098021130240)]} 0 1
[junit4:junit4] 2> 15582 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[56 (1429636098125987840)]} 0 1
[junit4:junit4] 2> 15583 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10056 (1429636098125987841)]} 0 2
[junit4:junit4] 2> 15586 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[56 (1429636098130182144)]} 0 2
[junit4:junit4] 2> 15586 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10056 (1429636098130182145)]} 0 1
[junit4:junit4] 2> 15605 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15606 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40333_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40333/bad/s"}
[junit4:junit4] 2> 15609 T1579 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> 15609 T1595 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> 15609 T1566 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> 15609 T1559 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> 15610 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[57 (1429636098155347969)]} 0 2
[junit4:junit4] 2> 15611 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10057 (1429636098155347968)]} 0 2
[junit4:junit4] 2> C68_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40333_bad%2Fs, base_url=http://127.0.0.1:40333/bad/s}
[junit4:junit4] 2> 15618 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1429636098158493696)]} 0 3
[junit4:junit4] 2> 15619 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10057 (1429636098159542272)]} 0 4
[junit4:junit4] 2> 15620 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[57 (1429636098158493696)]} 0 8
[junit4:junit4] 2> 15620 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10057 (1429636098159542272)]} 0 7
[junit4:junit4] 2> 15680 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10058 (1429636098228748288)]} 0 1
[junit4:junit4] 2> 15681 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[58 (1429636098228748289)]} 0 2
[junit4:junit4] 2> 15687 T1589 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1429636098232942592)]} 0 1
[junit4:junit4] 2> 15687 T1590 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10058 (1429636098232942593)]} 0 1
[junit4:junit4] 2> 15688 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[58 (1429636098232942592)]} 0 5
[junit4:junit4] 2> 15688 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10058 (1429636098232942593)]} 0 5
[junit4:junit4] 2> 15735 T1537 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15736 T1537 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15740 T1537 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@2068a976
[junit4:junit4] 2> 15747 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10059 (1429636098299002881)]} 0 1
[junit4:junit4] 2> 15748 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[59 (1429636098299002880)]} 0 2
[junit4:junit4] 2> 15754 T1537 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=4,adds=4,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=18,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 15756 T1537 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 15757 T1537 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 15757 T1591 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {} 0 1
[junit4:junit4] 2> 15757 T1588 C68 P40333 /update {distrib.from=http://127.0.0.1:40375/bad/s/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10059 (1429636098304245760)]} 0 2
[junit4:junit4] 2> 15757 T1537 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 15762 T1591 C68 P40333 oasc.SolrException.log SEVERE org.apache.solr.common.SolrException: SolrCoreState already closed
[junit4:junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:85)
[junit4:junit4] 2> at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:153)
[junit4:junit4] 2> at org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:69)
[junit4:junit4] 2> at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:51)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:451)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:587)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:346)
[junit4:junit4] 2> at org.apache.solr.update.processor.LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:100)
[junit4:junit4] 2> at org.apache.solr.handler.loader.XMLLoader.processUpdate(XMLLoader.java:246)
[junit4:junit4] 2> at org.apache.solr.handler.loader.XMLLoader.load(XMLLoader.java:173)
[junit4:junit4] 2> at org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:92)
[junit4:junit4] 2> at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:74)
[junit4:junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1811)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:637)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:343)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:141)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:135)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453)
[junit4:junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:275)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1074)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
[junit4:junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
[junit4:junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:365)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:948)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
[junit4:junit4] 2> at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
[junit4:junit4] 2> at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
[junit4:junit4] 2> at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 15762 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10059 (1429636098304245760)]} 0 12
[junit4:junit4] 2> 15764 T1591 C68 P40333 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@2068a976
[junit4:junit4] 2> 15764 T1591 C68 P40333 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=1,adds=5,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=47,cumulative_deletesById=18,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 15768 T1537 C68 P40333 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78),segFN=segments_3,generation=3,filenames=[_0.fnm, _0_Lucene42_0.dvd, _0_Lucene41_0.pos, _0_1.del, _0_Lucene42_0.dvm, _0.nvm, _0_Lucene41_0.doc, _0.nvd, _0.fdx, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, segments_3, _0.fdt]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78),segFN=segments_4,generation=4,filenames=[_1_Lucene41_0.doc, _0_Lucene42_0.dvd, _1_Lucene42_0.dvm, _0_Lucene41_0.pos, _0_Lucene42_0.dvm, _1_Lucene42_0.dvd, _1.fnm, _0.nvd, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _1.nvm, _0.fnm, _1_Lucene41_0.tim, _1.nvd, _0_1.del, _1_Lucene41_0.tip, _0.nvm, _1_Lucene41_0.pos, _1.fdx, _0_Lucene41_0.doc, _1.fdt, _1.si, _0.fdx, _0.fdt, segments_4]
[junit4:junit4] 2> 15768 T1537 C68 P40333 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_1_Lucene41_0.doc, _0_Lucene42_0.dvd, _1_Lucene42_0.dvm, _0_Lucene41_0.pos, _0_Lucene42_0.dvm, _1_Lucene42_0.dvd, _1.fnm, _0.nvd, _0.si, _0_Lucene41_0.tim, _0_Lucene41_0.tip, _1.nvm, _0.fnm, _1_Lucene41_0.tim, _1.nvd, _0_1.del, _1_Lucene41_0.tip, _0.nvm, _1_Lucene41_0.pos, _1.fdx, _0_Lucene41_0.doc, _1.fdt, _1.si, _0.fdx, _0.fdt, segments_4]
[junit4:junit4] 2> 15772 T1591 C68 P40333 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 15772 T1537 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 15773 T1542 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d716711dc0008
[junit4:junit4] 2> 15775 T1566 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> 15775 T1537 oaz.ZooKeeper.close Session: 0x13d716711dc0008 closed
[junit4:junit4] 2> 15775 T1539 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:37871 which had sessionid 0x13d716711dc0008
[junit4:junit4] 2> 15776 T1575 C70 P40375 oasc.SolrException.log SEVERE shard update error StdNode: http://127.0.0.1:40333/bad/s/collection1/:org.apache.solr.common.SolrException: Server at http://127.0.0.1:40333/bad/s/collection1 returned non ok status:503, message:Service Unavailable
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:373)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4] 2> at org.apache.solr.update.SolrCmdDistributor$1.call(SolrCmdDistributor.java:332)
[junit4:junit4] 2> at org.apache.solr.update.SolrCmdDistributor$1.call(SolrCmdDistributor.java:306)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 15776 T1579 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15776 T1559 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15777 T1579 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 15777 T1575 C70 P40375 oasup.DistributedUpdateProcessor.doFinish try and ask http://127.0.0.1:40333/bad/s to recover
[junit4:junit4] 2> 15778 T1566 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15777 T1559 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 15778 T1575 C70 P40375 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15785 T1575 C70 P40375 oasup.DistributedUpdateProcessor.doFinish Could not tell a replica to recover org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:40333/bad/s
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:409)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doFinish(DistributedUpdateProcessor.java:440)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.finish(DistributedUpdateProcessor.java:1086)
[junit4:junit4] 2> at org.apache.solr.update.processor.LogUpdateProcessor.finish(LogUpdateProcessorFactory.java:179)
[junit4:junit4] 2> at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:83)
[junit4:junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1811)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:637)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:343)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:141)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:135)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453)
[junit4:junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:275)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1074)
[junit4:junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
[junit4:junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
[junit4:junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
[junit4:junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:365)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:948)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
[junit4:junit4] 2> at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
[junit4:junit4] 2> at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
[junit4:junit4] 2> at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2> Caused by: org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:40333 refused
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:190)
[junit4:junit4] 2> at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
[junit4:junit4] 2> ... 35 more
[junit4:junit4] 2> Caused by: java.net.ConnectException: Connection refused
[junit4:junit4] 2> at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4:junit4] 2> at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
[junit4:junit4] 2> at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
[junit4:junit4] 2> at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
[junit4:junit4] 2> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
[junit4:junit4] 2> at java.net.Socket.connect(Socket.java:529)
[junit4:junit4] 2> at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] 2> ... 42 more
[junit4:junit4] 2>
[junit4:junit4] 2> 15787 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[59 (1429636098304245761)]} 0 36
[junit4:junit4] 2> 15797 T1537 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/bad/s,null}
[junit4:junit4] 2> 15809 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10060 (1429636098362966016)]} 0 2
[junit4:junit4] 2> 15814 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10060 (1429636098368208896)]} 0 2
[junit4:junit4] 2> 15832 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[60 (1429636098388131840)]} 0 1
[junit4:junit4] 2> 15834 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10061 (1429636098390228992)]} 0 1
[junit4:junit4] 2> 15837 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[60 (1429636098393374720)]} 0 2
[junit4:junit4] 2> 15838 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10061 (1429636098394423296)]} 0 1
[junit4:junit4] 2> 15856 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10062 (1429636098413297664)]} 0 1
[junit4:junit4] 2> 15857 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[61 (1429636098414346240)]} 0 1
[junit4:junit4] 2> 15860 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10062 (1429636098417491968)]} 0 1
[junit4:junit4] 2> 15862 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[61 (1429636098419589120)]} 0 1
[junit4:junit4] 2> 15880 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[62 (1429636098438463488)]} 0 1
[junit4:junit4] 2> 15884 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[62 (1429636098442657792)]} 0 1
[junit4:junit4] 2> 15920 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10063 (1429636098480406528)]} 0 1
[junit4:junit4] 2> 15924 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10063 (1429636098484600832)]} 0 1
[junit4:junit4] 2> 15944 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[63 (1429636098505572352)]} 0 2
[junit4:junit4] 2> 15948 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[63 (1429636098509766656)]} 0 1
[junit4:junit4] 2> 16024 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[10050 (-1429636098590507008)]} 0 1
[junit4:junit4] 2> 16027 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10050 (-1429636098593652736)]} 0 0
[junit4:junit4] 2> 16031 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10064 (1429636098596798464)]} 0 1
[junit4:junit4] 2> 16036 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10064 (1429636098602041344)]} 0 2
[junit4:junit4] 2> 16048 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[50 (-1429636098614624256)]} 0 1
[junit4:junit4] 2> 16051 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[50 (-1429636098618818560)]} 0 0
[junit4:junit4] 2> 16055 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[64 (1429636098621964288)]} 0 1
[junit4:junit4] 2> 16061 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[64 (1429636098628255744)]} 0 1
[junit4:junit4] 2> 16087 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10065 (1429636098655518720)]} 0 1
[junit4:junit4] 2> 16091 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10065 (1429636098659713024)]} 0 1
[junit4:junit4] 2> 16113 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[65 (1429636098682781696)]} 0 1
[junit4:junit4] 2> 16118 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[65 (1429636098688024576)]} 0 2
[junit4:junit4] 2> 16192 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10057 (-1429636098766667776)]} 0 1
[junit4:junit4] 2> 16195 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[10057 (-1429636098769813504)]} 0 0
[junit4:junit4] 2> 16199 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10066 (1429636098772959232)]} 0 1
[junit4:junit4] 2> 16204 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10066 (1429636098778202112)]} 0 2
[junit4:junit4] 2> 16218 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[57 (-1429636098793930753)]} 0 0
[junit4:junit4] 2> 16219 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10067 (1429636098793930752)]} 0 1
[junit4:junit4] 2> 16222 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[57 (-1429636098798125056)]} 0 1
[junit4:junit4] 2> 16224 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10067 (1429636098799173632)]} 0 2
[junit4:junit4] 2> 16226 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[66 (1429636098801270784)]} 0 1
[junit4:junit4] 2> 16231 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[66 (1429636098806513664)]} 0 2
[junit4:junit4] 2> 16243 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10068 (1429636098818048000)]} 0 2
[junit4:junit4] 2> 16246 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[67 (1429636098822242304)]} 0 1
[junit4:junit4] 2> 16247 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[10068 (1429636098823290880)]} 0 2
[junit4:junit4] 2> 16251 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[67 (1429636098827485184)]} 0 2
[junit4:junit4] 2> 16269 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[68 (1429636098846359552)]} 0 1
[junit4:junit4] 2> 16274 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[68 (1429636098851602432)]} 0 2
[junit4:junit4] 2> 16305 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10069 (1429636098884108288)]} 0 1
[junit4:junit4] 2> 16310 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[10069 (1429636098889351168)]} 0 1
[junit4:junit4] 2> 16332 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[69 (1429636098912419840)]} 0 1
[junit4:junit4] 2> 16337 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[69 (1429636098917662720)]} 0 1
[junit4:junit4] 2> 16406 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[10058 (-1429636098991063040)]} 0 0
[junit4:junit4] 2> 16410 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10058 (-1429636098995257344)]} 0 1
[junit4:junit4] 2> 16414 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10070 (1429636098998403072)]} 0 1
[junit4:junit4] 2> 16418 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10070 (1429636099002597376)]} 0 1
[junit4:junit4] 2> 16433 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[58 (-1429636099019374592)]} 0 0
[junit4:junit4] 2> 16437 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[58 (-1429636099023568896)]} 0 1
[junit4:junit4] 2> 16441 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[70 (1429636099026714624)]} 0 1
[junit4:junit4] 2> 16446 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[70 (1429636099030908928)]} 0 2
[junit4:junit4] 2> 16504 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10071 (1429636099092774912)]} 0 2
[junit4:junit4] 2> 16508 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10071 (1429636099096969216)]} 0 1
[junit4:junit4] 2> 16531 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[71 (1429636099121086464)]} 0 1
[junit4:junit4] 2> 16536 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[71 (1429636099126329344)]} 0 2
[junit4:junit4] 2> 16546 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10059 (-1429636099137863680)]} 0 0
[junit4:junit4] 2> 16550 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10059 (-1429636099142057984)]} 0 1
[junit4:junit4] 2> 16554 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10072 (1429636099145203712)]} 0 1
[junit4:junit4] 2> 16558 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10072 (1429636099149398016)]} 0 1
[junit4:junit4] 2> 16574 T1552 C69 P45161 /update {wt=javabin&version=2} {delete=[59 (-1429636099167223808)]} 0 0
[junit4:junit4] 2> 16577 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[59 (-1429636099170369536)]} 0 0
[junit4:junit4] 2> 16582 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[72 (1429636099174563840)]} 0 2
[junit4:junit4] 2> 16586 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[72 (1429636099178758144)]} 0 1
[junit4:junit4] 2> 16614 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10063 (-1429636099208118272)]} 0 1
[junit4:junit4] 2> 16617 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10063 (-1429636099212312576)]} 0 0
[junit4:junit4] 2> 16621 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10073 (1429636099215458304)]} 0 1
[junit4:junit4] 2> 16625 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10073 (1429636099219652608)]} 0 1
[junit4:junit4] 2> 16642 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[63 (-1429636099238526976)]} 0 1
[junit4:junit4] 2> 16645 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[63 (-1429636099241672704)]} 0 0
[junit4:junit4] 2> 16649 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[73 (1429636099244818432)]} 0 1
[junit4:junit4] 2> 16654 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[73 (1429636099250061312)]} 0 2
[junit4:junit4] 2> 16675 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10065 (-1429636099273129984)]} 0 1
[junit4:junit4] 2> 16678 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10065 (-1429636099276275712)]} 0 0
[junit4:junit4] 2> 16682 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10074 (1429636099279421440)]} 0 1
[junit4:junit4] 2> 16687 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10074 (1429636099284664320)]} 0 2
[junit4:junit4] 2> 16703 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[65 (-1429636099302490112)]} 0 0
[junit4:junit4] 2> 16706 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[65 (-1429636099305635840)]} 0 0
[junit4:junit4] 2> 16711 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[74 (1429636099309830144)]} 0 2
[junit4:junit4] 2> 16715 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[74 (1429636099314024448)]} 0 1
[junit4:junit4] 2> 16717 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10066 (-1429636099317170176)]} 0 0
[junit4:junit4] 2> 16721 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10066 (-1429636099320315904)]} 0 1
[junit4:junit4] 2> 16725 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10075 (1429636099324510208)]} 0 1
[junit4:junit4] 2> 16729 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10075 (1429636099328704512)]} 0 1
[junit4:junit4] 2> 16746 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[66 (-1429636099347578880)]} 0 1
[junit4:junit4] 2> 16749 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[66 (-1429636099350724608)]} 0 0
[junit4:junit4] 2> 16754 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[75 (1429636099354918912)]} 0 2
[junit4:junit4] 2> 16758 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[75 (1429636099359113216)]} 0 1
[junit4:junit4] 2> 16760 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[10068 (-1429636099361210368)]} 0 1
[junit4:junit4] 2> 16763 T1574 C70 P40375 /update {wt=javabin&version=2} {delete=[10068 (-1429636099365404672)]} 0 0
[junit4:junit4] 2> 16767 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[10076 (1429636099368550400)]} 0 1
[junit4:junit4] 2> 16772 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10076 (1429636099373793280)]} 0 2
[junit4:junit4] 2> 16789 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[68 (-1429636099392667648)]} 0 1
[junit4:junit4] 2> 16792 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[68 (-1429636099395813376)]} 0 0
[junit4:junit4] 2> 16797 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[76 (1429636099398959104)]} 0 2
[junit4:junit4] 2> 16801 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[76 (1429636099404201984)]} 0 1
[junit4:junit4] 2> 16808 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10077 (1429636099411542016)]} 0 1
[junit4:junit4] 2> 16812 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10077 (1429636099415736320)]} 0 1
[junit4:junit4] 2> 16837 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[77 (1429636099441950720)]} 0 1
[junit4:junit4] 2> 16842 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[77 (1429636099447193600)]} 0 2
[junit4:junit4] 2> 16896 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10069 (-1429636099503816704)]} 0 1
[junit4:junit4] 2> 16899 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10069 (-1429636099508011008)]} 0 0
[junit4:junit4] 2> 16903 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10078 (1429636099511156736)]} 0 1
[junit4:junit4] 2> 16907 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10078 (1429636099515351040)]} 0 1
[junit4:junit4] 2> 16925 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[69 (-1429636099535273984)]} 0 0
[junit4:junit4] 2> 16929 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[69 (-1429636099538419712)]} 0 1
[junit4:junit4] 2> 16933 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[78 (1429636099542614016)]} 0 2
[junit4:junit4] 2> 16934 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10073 (-1429636099544711168)]} 0 1
[junit4:junit4] 2> 16937 T1572 C70 P40375 /update {wt=javabin&version=2} {delete=[10073 (-1429636099547856896)]} 0 0
[junit4:junit4] 2> 16937 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[78 (1429636099546808320)]} 0 1
[junit4:junit4] 2> 16941 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10079 (1429636099551002624)]} 0 1
[junit4:junit4] 2> 16946 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10079 (1429636099556245504)]} 0 2
[junit4:junit4] 2> 16964 T1553 C69 P45161 /update {wt=javabin&version=2} {delete=[73 (-1429636099576168448)]} 0 0
[junit4:junit4] 2> 16967 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[73 (-1429636099579314176)]} 0 0
[junit4:junit4] 2> 16972 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[79 (1429636099583508480)]} 0 1
[junit4:junit4] 2> 16976 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[79 (1429636099587702784)]} 0 1
[junit4:junit4] 2> 16978 T1555 C69 P45161 /update {wt=javabin&version=2} {add=[10080 (1429636099589799936)]} 0 1
[junit4:junit4] 2> 16983 T1573 C70 P40375 /update {wt=javabin&version=2} {add=[10080 (1429636099595042816)]} 0 2
[junit4:junit4] 2> 16991 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[10081 (1429636099603431424)]} 0 1
[junit4:junit4] 2> 16996 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10081 (1429636099608674304)]} 0 2
[junit4:junit4] 2> 17010 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[80 (1429636099622305792)]} 0 2
[junit4:junit4] 2> 17015 T1575 C70 P40375 /update {wt=javabin&version=2} {add=[80 (1429636099628597248)]} 0 2
[junit4:junit4] 2> 17024 T1554 C69 P45161 /update {wt=javabin&version=2} {add=[81 (1429636099638034432)]} 0 1
[junit4:junit4] 2> 17027 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[81 (1429636099641180160)]} 0 1
[junit4:junit4] 2> 17075 T1595 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 17075 T1595 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> 17075 T1595 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 17075 T1595 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 17085 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10074 (-1429636099701997568)]} 0 1
[junit4:junit4] 2> 17088 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10074 (-1429636099706191872)]} 0 0
[junit4:junit4] 2> 17093 T1553 C69 P45161 /update {wt=javabin&version=2} {add=[10082 (1429636099710386176)]} 0 2
[junit4:junit4] 2> 17097 T1574 C70 P40375 /update {wt=javabin&version=2} {add=[10082 (1429636099714580480)]} 0 1
[junit4:junit4] 2> 17114 T1560 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17115 T1560 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:40333_bad%2Fs",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40333/bad/s"}
[junit4:junit4] 2> 17116 T1554 C69 P45161 /update {wt=javabin&version=2} {delete=[74 (-1429636099734503424)]} 0 1
[junit4:junit4] 2> 17119 T1575 C70 P40375 /update {wt=javabin&version=2} {delete=[74 (-1429636099738697728)]} 0 1
[junit4:junit4] 2> 17123 T1579 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> 17123 T1566 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> 17123 T1559 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> 17124 T1552 C69 P45161 /update {wt=javabin&version=2} {add=[82 (1429636099741843456)]} 0 2
[junit4:junit4] 2> 17129 T1572 C70 P40375 /update {wt=javabin&version=2} {add=[82 (1429636099747086336)]} 0 2
[junit4:junit4] 2> 17193 T1555 C69 P45161 /update {wt=javabin&version=2} {delete=[10077 (-1429636099816292352)]} 0 0
[junit4:junit4] 2> 17197 T1573 C70 P40375 /update {wt=javabin&version=2} {delete=[10077 (-1429636099820486656)]} 0 1
[junit4:junit4] 2> 1
[...truncated too long message...]
kerImpl exited loop!
[junit4:junit4] 2> 35652 T1619 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 35652 T1619 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> 35652 T1619 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 35653 T1619 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=HighCompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=165), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=165)), sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=lt, timezone=W-SU
[junit4:junit4] 2> NOTE: Linux 3.2.0-38-generic amd64/Sun Microsystems Inc. 1.6.0_41 (64-bit)/cpus=8,threads=3,free=341690656,total=488235008
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SuggesterTest, TestRandomDVFaceting, SoftAutoCommitTest, TestIBSimilarityFactory, TestSolrCoreProperties, TestTrie, AnalysisAfterCoreReloadTest, QueryElevationComponentTest, PluginInfoTest, SliceStateUpdateTest, DateFieldTest, TestSolrIndexConfig, LoggingHandlerTest, TestFastWriter, LukeRequestHandlerTest, TermsComponentTest, TestReplicationHandler, TestConfig, TestQueryUtils, TestDynamicFieldResource, TestFieldCollectionResource, BinaryUpdateRequestHandlerTest, TestExtendedDismaxParser, TestXIncludeConfig, TestFuzzyAnalyzedSuggestions, SystemInfoHandlerTest, OverseerTest, AlternateDirectoryTest, ShardRoutingTest, IndexSchemaTest, RecoveryZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.seed=278DD685C355674C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=lt -Dtests.timezone=W-SU -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 0.00s J0 | RecoveryZkTest (suite) <<<
[junit4:junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=1596, name=coreLoadExecutor-654-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1479)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:34)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
[junit4:junit4] > at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
[junit4:junit4] > at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:744)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:872)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.create(CoreContainer.java:955)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:579)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
[junit4:junit4] > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
[junit4:junit4] > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@374d9299 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4669ed84)
[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=1598, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1479)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:520)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:986)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:878)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:870)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:34)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:272)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:224)
[junit4:junit4] > at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
[junit4:junit4] > at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
[junit4:junit4] > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a139fdf lockFactory=org.apache.lucene.store.NativeFSLockFactory@3abfae78)
[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:662)
[junit4:junit4] Completed on J0 in 35.79s, 1 test, 2 errors <<< FAILURES!
[...truncated 576 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:361: 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:1213: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:877: There were test failures: 272 suites, 1144 tests, 2 suite-level errors, 13 ignored (7 assumptions)
Total time: 38 minutes 36 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.6.0_41 -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure