lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-4.x-Windows (32bit/jdk1.6.0_41) - Build # 2653 - Failure!
Date Tue, 19 Mar 2013 22:08:56 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2653/
Java: 32bit/jdk1.6.0_41 -client -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=3836, name=coreLoadExecutor-2697-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=3836, name=coreLoadExecutor-2697-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:37)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
	at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
	at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
	at org.apache.solr.core.SolrCore.<init>(SolrCore.java: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@170f63 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9572b)
	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=3838, 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=3838, 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:37)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
	at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
	at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
	at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
	at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
	at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e)
	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 8750 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4]   2> 0 T3777 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 3 T3777 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\solrtest-RecoveryZkTest-1363730165765
[junit4:junit4]   2> 6 T3777 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 7 T3778 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 13 T3778 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 13 T3778 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 13 T3778 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 14 T3778 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 15 T3778 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\zookeeper\server1\data\version-2\snapshot.0
[junit4:junit4]   2> 105 T3777 oasc.ZkTestServer.run start zk server on port:54363
[junit4:junit4]   2> 105 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@133f27f
[junit4:junit4]   2> 107 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 108 T3783 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 108 T3783 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 108 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54366
[junit4:junit4]   2> 109 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54366
[junit4:junit4]   2> 109 T3781 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 120 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100000 with negotiated timeout 10000 for client /127.0.0.1:54366
[junit4:junit4]   2> 120 T3783 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100000, negotiated timeout = 10000
[junit4:junit4]   2> 121 T3784 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@133f27f name:ZooKeeperConnection Watcher:127.0.0.1:54363 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 121 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 121 T3777 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 126 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100000
[junit4:junit4]   2> 128 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100000 closed
[junit4:junit4]   2> 129 T3779 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d84a6f0100000, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:662)
[junit4:junit4]   2> 
[junit4:junit4]   2> 129 T3784 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 129 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1aaa0e
[junit4:junit4]   2> 131 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54366 which had sessionid 0x13d84a6f0100000
[junit4:junit4]   2> 132 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 133 T3785 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 134 T3785 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 134 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54369
[junit4:junit4]   2> 134 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54369
[junit4:junit4]   2> 136 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100001 with negotiated timeout 10000 for client /127.0.0.1:54369
[junit4:junit4]   2> 136 T3785 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100001, negotiated timeout = 10000
[junit4:junit4]   2> 137 T3786 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1aaa0e name:ZooKeeperConnection Watcher:127.0.0.1:54363/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 137 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 138 T3777 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 145 T3777 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 150 T3777 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 154 T3777 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 159 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 160 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 170 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 171 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 177 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 178 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 184 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 185 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 190 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 191 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 195 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 196 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 201 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 202 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 207 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 209 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 213 T3777 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 214 T3777 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 219 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100001
[junit4:junit4]   2> 221 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54369 which had sessionid 0x13d84a6f0100001
[junit4:junit4]   2> 222 T3786 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 222 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100001 closed
[junit4:junit4]   2> 651 T3777 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 658 T3777 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54370
[junit4:junit4]   2> 658 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 658 T3777 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 659 T3777 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983
[junit4:junit4]   2> 659 T3777 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983\solr.xml
[junit4:junit4]   2> 660 T3777 oasc.CoreContainer.<init> New CoreContainer 16672550
[junit4:junit4]   2> 661 T3777 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983\'
[junit4:junit4]   2> 661 T3777 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983\'
[junit4:junit4]   2> 742 T3777 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 743 T3777 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 743 T3777 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 744 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 745 T3777 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 746 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 747 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 748 T3777 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 748 T3777 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 748 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 767 T3777 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 792 T3777 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54363/solr
[junit4:junit4]   2> 793 T3777 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 793 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@e2ef08
[junit4:junit4]   2> 795 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 796 T3796 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 797 T3796 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 797 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54375
[junit4:junit4]   2> 797 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54375
[junit4:junit4]   2> 809 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100002 with negotiated timeout 20000 for client /127.0.0.1:54375
[junit4:junit4]   2> 809 T3796 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100002, negotiated timeout = 20000
[junit4:junit4]   2> 810 T3797 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e2ef08 name:ZooKeeperConnection Watcher:127.0.0.1:54363 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 810 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 812 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100002
[junit4:junit4]   2> 814 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100002 closed
[junit4:junit4]   2> 814 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54375 which had sessionid 0x13d84a6f0100002
[junit4:junit4]   2> 814 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 814 T3797 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 818 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@15563c3
[junit4:junit4]   2> 820 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 821 T3798 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 821 T3798 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 821 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54378
[junit4:junit4]   2> 822 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54378
[junit4:junit4]   2> 824 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100003 with negotiated timeout 20000 for client /127.0.0.1:54378
[junit4:junit4]   2> 824 T3798 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100003, negotiated timeout = 20000
[junit4:junit4]   2> 824 T3799 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15563c3 name:ZooKeeperConnection Watcher:127.0.0.1:54363/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 825 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 827 T3777 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 831 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 833 T3777 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 838 T3777 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 842 T3777 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54370_
[junit4:junit4]   2> 843 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:54370_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:54370_
[junit4:junit4]   2> 844 T3777 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54370_
[junit4:junit4]   2> 857 T3777 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 867 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 868 T3777 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 873 T3777 oasc.Overseer.start Overseer (id=89373420144295939-127.0.0.1:54370_-n_0000000000) starting
[junit4:junit4]   2> 874 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 876 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 879 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 881 T3777 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 886 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 889 T3801 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 890 T3777 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 894 T3777 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 897 T3777 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 901 T3800 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 905 T3802 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983\collection1
[junit4:junit4]   2> 905 T3802 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 906 T3802 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 906 T3802 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 909 T3802 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983\collection1\'
[junit4:junit4]   2> 910 T3802 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 910 T3802 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983/collection1/lib/README' to classloader
[junit4:junit4]   2> 978 T3802 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 1058 T3802 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 1059 T3802 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 1069 T3802 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 2035 T3802 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 2050 T3802 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 2056 T3802 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 2074 T3802 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 2080 T3802 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 2086 T3802 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 2088 T3802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 2088 T3802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 2088 T3802 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 2090 T3802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 2090 T3802 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 2090 T3802 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 2091 T3802 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1363730165983\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/control/data\
[junit4:junit4]   2> 2091 T3802 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e80740
[junit4:junit4]   2> 2091 T3802 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 2091 T3802 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/control/data\ forceNew: false
[junit4:junit4]   2> 2091 T3802 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/control/data\index/
[junit4:junit4]   2> 2092 T3802 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\control\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 2093 T3802 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/control/data\index forceNew: false
[junit4:junit4]   2> 2097 T3802 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df0b15 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15bf462),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 2097 T3802 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 2102 T3802 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 2102 T3802 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 2103 T3802 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 2103 T3802 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 2104 T3802 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 2104 T3802 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 2104 T3802 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 2105 T3802 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 2105 T3802 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 2123 T3802 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 2133 T3802 oass.SolrIndexSearcher.<init> Opening Searcher@9090c main
[junit4:junit4]   2> 2134 T3802 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\control\data\tlog
[junit4:junit4]   2> 2137 T3802 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 2137 T3802 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 2143 T3803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9090c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 2144 T3802 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 2144 T3802 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 2356 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2357 T3800 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:54370_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54370"}
[junit4:junit4]   2> 2357 T3800 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2358 T3800 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2365 T3799 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> 3035 T3802 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 3035 T3802 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54370 collection:control_collection shard:shard1
[junit4:junit4]   2> 3036 T3802 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 3049 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 3051 T3802 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 3051 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3056 T3802 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 3056 T3802 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 3056 T3802 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54370/collection1/
[junit4:junit4]   2> 3057 T3802 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 3057 T3802 oasc.SyncStrategy.syncToMe http://127.0.0.1:54370/collection1/ has no replicas
[junit4:junit4]   2> 3057 T3802 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54370/collection1/
[junit4:junit4]   2> 3057 T3802 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 3066 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3687 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3701 T3799 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> 3739 T3802 oasc.ZkController.register We are http://127.0.0.1:54370/collection1/ and leader is http://127.0.0.1:54370/collection1/
[junit4:junit4]   2> 3739 T3802 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54370
[junit4:junit4]   2> 3739 T3802 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3739 T3802 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3739 T3802 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3750 T3802 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3751 T3777 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 3751 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3751 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3764 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3765 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6ce62f
[junit4:junit4]   2> 3768 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3769 T3805 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 3769 T3805 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 3769 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54381
[junit4:junit4]   2> 3770 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54381
[junit4:junit4]   2> 3772 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100004 with negotiated timeout 10000 for client /127.0.0.1:54381
[junit4:junit4]   2> 3772 T3805 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100004, negotiated timeout = 10000
[junit4:junit4]   2> 3772 T3806 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ce62f name:ZooKeeperConnection Watcher:127.0.0.1:54363/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3773 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3774 T3777 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3776 T3777 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 4146 T3777 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 4149 T3777 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54382
[junit4:junit4]   2> 4150 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 4151 T3777 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 4151 T3777 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537
[junit4:junit4]   2> 4151 T3777 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537\solr.xml
[junit4:junit4]   2> 4151 T3777 oasc.CoreContainer.<init> New CoreContainer 21089448
[junit4:junit4]   2> 4151 T3777 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537\'
[junit4:junit4]   2> 4152 T3777 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537\'
[junit4:junit4]   2> 4200 T3777 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 4201 T3777 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 4202 T3777 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 4210 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 4210 T3777 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 4210 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 4211 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 4211 T3777 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 4211 T3777 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 4211 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 4225 T3777 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4247 T3777 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54363/solr
[junit4:junit4]   2> 4248 T3777 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4248 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@59649b
[junit4:junit4]   2> 4250 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4251 T3816 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 4252 T3816 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 4252 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54387
[junit4:junit4]   2> 4252 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54387
[junit4:junit4]   2> 4264 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100005 with negotiated timeout 20000 for client /127.0.0.1:54387
[junit4:junit4]   2> 4264 T3816 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100005, negotiated timeout = 20000
[junit4:junit4]   2> 4265 T3817 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59649b name:ZooKeeperConnection Watcher:127.0.0.1:54363 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4265 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4266 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100005
[junit4:junit4]   2> 4268 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100005 closed
[junit4:junit4]   2> 4268 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54387 which had sessionid 0x13d84a6f0100005
[junit4:junit4]   2> 4268 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 4269 T3817 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4273 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@8f7cf7
[junit4:junit4]   2> 4276 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4277 T3818 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 4277 T3818 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 4277 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54390
[junit4:junit4]   2> 4277 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54390
[junit4:junit4]   2> 4279 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100006 with negotiated timeout 20000 for client /127.0.0.1:54390
[junit4:junit4]   2> 4279 T3818 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100006, negotiated timeout = 20000
[junit4:junit4]   2> 4280 T3819 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8f7cf7 name:ZooKeeperConnection Watcher:127.0.0.1:54363/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4280 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4281 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4283 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4287 T3777 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 5025 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5027 T3800 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:54370_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54370"}
[junit4:junit4]   2> 5035 T3819 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> 5035 T3806 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> 5036 T3799 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> 5168 T3777 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54382_
[junit4:junit4]   2> 5168 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100006 type:delete cxid:0xf zxid:0x4e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:54382_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:54382_
[junit4:junit4]   2> 5170 T3777 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54382_
[junit4:junit4]   2> 5174 T3799 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> 5174 T3806 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5174 T3806 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> 5175 T3819 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5175 T3819 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> 5178 T3799 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 5193 T3820 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537\collection1
[junit4:junit4]   2> 5193 T3820 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 5194 T3820 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 5195 T3820 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 5198 T3820 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537\collection1\'
[junit4:junit4]   2> 5199 T3820 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 5201 T3820 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537/collection1/lib/README' to classloader
[junit4:junit4]   2> 5263 T3820 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 5334 T3820 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 5335 T3820 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 5341 T3820 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 6128 T3820 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 6139 T3820 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 6144 T3820 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 6160 T3820 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 6164 T3820 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 6168 T3820 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 6171 T3820 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 6172 T3820 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 6172 T3820 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 6173 T3820 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 6173 T3820 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 6173 T3820 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 6174 T3820 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1363730169537\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty1\
[junit4:junit4]   2> 6174 T3820 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e80740
[junit4:junit4]   2> 6174 T3820 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 6174 T3820 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty1\ forceNew: false
[junit4:junit4]   2> 6174 T3820 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty1\index/
[junit4:junit4]   2> 6175 T3820 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 6176 T3820 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty1\index forceNew: false
[junit4:junit4]   2> 6179 T3820 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40e710 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b123e9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 6179 T3820 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 6184 T3820 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 6184 T3820 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 6184 T3820 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 6184 T3820 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 6185 T3820 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 6185 T3820 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 6185 T3820 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 6186 T3820 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 6186 T3820 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 6194 T3820 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 6198 T3820 oass.SolrIndexSearcher.<init> Opening Searcher@125536b main
[junit4:junit4]   2> 6198 T3820 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\jetty1\tlog
[junit4:junit4]   2> 6201 T3820 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 6201 T3820 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 6213 T3821 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@125536b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 6214 T3820 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 6214 T3820 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6360 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6361 T3800 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:54382_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54382"}
[junit4:junit4]   2> 6361 T3800 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4]   2> 6361 T3800 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6370 T3799 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> 6370 T3806 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> 6371 T3819 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> 7098 T3820 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7098 T3820 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54382 collection:collection1 shard:shard1
[junit4:junit4]   2> 7099 T3820 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7111 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100006 type:delete cxid:0x4c zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7112 T3820 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7113 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100006 type:create cxid:0x4d zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7117 T3820 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7117 T3820 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7117 T3820 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54382/collection1/
[junit4:junit4]   2> 7117 T3820 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7117 T3820 oasc.SyncStrategy.syncToMe http://127.0.0.1:54382/collection1/ has no replicas
[junit4:junit4]   2> 7117 T3820 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54382/collection1/
[junit4:junit4]   2> 7117 T3820 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7124 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100006 type:create cxid:0x58 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7696 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7713 T3799 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> 7714 T3806 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> 7714 T3819 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> 7753 T3820 oasc.ZkController.register We are http://127.0.0.1:54382/collection1/ and leader is http://127.0.0.1:54382/collection1/
[junit4:junit4]   2> 7753 T3820 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54382
[junit4:junit4]   2> 7754 T3820 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 7754 T3820 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 7754 T3820 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7757 T3820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7759 T3777 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 7759 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 7759 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8196 T3777 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8199 T3777 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54391
[junit4:junit4]   2> 8200 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8201 T3777 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8203 T3777 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526
[junit4:junit4]   2> 8203 T3777 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\solr.xml
[junit4:junit4]   2> 8204 T3777 oasc.CoreContainer.<init> New CoreContainer 13703829
[junit4:junit4]   2> 8205 T3777 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\'
[junit4:junit4]   2> 8205 T3777 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\'
[junit4:junit4]   2> 8255 T3777 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8255 T3777 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8255 T3777 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8255 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8256 T3777 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8256 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8257 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8257 T3777 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8258 T3777 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8258 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8278 T3777 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8300 T3777 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54363/solr
[junit4:junit4]   2> 8300 T3777 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8300 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1d79e22
[junit4:junit4]   2> 8302 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8303 T3832 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 8304 T3832 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 8304 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54396
[junit4:junit4]   2> 8304 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54396
[junit4:junit4]   2> 8318 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100007 with negotiated timeout 20000 for client /127.0.0.1:54396
[junit4:junit4]   2> 8318 T3832 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100007, negotiated timeout = 20000
[junit4:junit4]   2> 8318 T3833 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d79e22 name:ZooKeeperConnection Watcher:127.0.0.1:54363 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8319 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8320 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100007
[junit4:junit4]   2> 8322 T3833 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8322 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100007 closed
[junit4:junit4]   2> 8322 T3779 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d84a6f0100007, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:662)
[junit4:junit4]   2> 
[junit4:junit4]   2> 8323 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8324 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54396 which had sessionid 0x13d84a6f0100007
[junit4:junit4]   2> 8327 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@a94c20
[junit4:junit4]   2> 8329 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8330 T3834 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 8330 T3834 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 8330 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54399
[junit4:junit4]   2> 8330 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54399
[junit4:junit4]   2> 8333 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100008 with negotiated timeout 20000 for client /127.0.0.1:54399
[junit4:junit4]   2> 8333 T3834 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100008, negotiated timeout = 20000
[junit4:junit4]   2> 8333 T3835 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a94c20 name:ZooKeeperConnection Watcher:127.0.0.1:54363/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8334 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8335 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8337 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8342 T3777 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9039 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9040 T3800 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:54382_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54382"}
[junit4:junit4]   2> 9050 T3819 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> 9050 T3806 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> 9051 T3835 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> 9050 T3799 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> 9221 T3777 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54391_
[junit4:junit4]   2> 9223 T3782 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d84a6f0100008 type:delete cxid:0xf zxid:0x72 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:54391_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:54391_
[junit4:junit4]   2> 9225 T3777 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54391_
[junit4:junit4]   2> 9228 T3799 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> 9228 T3835 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> 9230 T3806 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9231 T3806 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> 9231 T3819 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9232 T3819 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> 9236 T3835 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9238 T3799 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9255 T3836 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\collection1
[junit4:junit4]   2> 9255 T3836 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9256 T3836 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9256 T3836 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9258 T3836 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\collection1\'
[junit4:junit4]   2> 9259 T3836 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9260 T3836 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526/collection1/lib/README' to classloader
[junit4:junit4]   2> 9321 T3836 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 9392 T3836 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9393 T3836 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9398 T3836 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 10189 T3836 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 10201 T3836 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 10205 T3836 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 10223 T3836 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10226 T3836 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10231 T3836 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10234 T3836 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 10234 T3836 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 10235 T3836 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10236 T3836 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 10237 T3836 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 10237 T3836 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 10237 T3836 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\
[junit4:junit4]   2> 10237 T3836 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@e80740
[junit4:junit4]   2> 10237 T3836 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 10237 T3836 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\ forceNew: false
[junit4:junit4]   2> 10238 T3836 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\index/
[junit4:junit4]   2> 10238 T3836 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 10238 T3836 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\index forceNew: false
[junit4:junit4]   2> 10243 T3836 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18a9eb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b33),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 10243 T3836 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 10247 T3836 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 10247 T3836 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 10247 T3836 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 10249 T3836 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 10249 T3836 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 10249 T3836 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 10249 T3836 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 10250 T3836 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 10250 T3836 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 10257 T3836 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 10264 T3836 oass.SolrIndexSearcher.<init> Opening Searcher@63dd0f main
[junit4:junit4]   2> 10264 T3836 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\jetty2\tlog
[junit4:junit4]   2> 10266 T3836 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 10267 T3836 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 10279 T3837 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63dd0f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 10279 T3836 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 10279 T3836 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10375 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10375 T3800 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:54391_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54391"}
[junit4:junit4]   2> 10375 T3800 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 10375 T3800 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 10383 T3806 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> 10383 T3819 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> 10384 T3799 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> 10384 T3835 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> 11149 T3836 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11149 T3836 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54391 collection:collection1 shard:shard1
[junit4:junit4]   2> 11156 T3836 oasc.ZkController.register We are http://127.0.0.1:54391/collection1/ and leader is http://127.0.0.1:54382/collection1/
[junit4:junit4]   2> 11156 T3836 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54391
[junit4:junit4]   2> 11156 T3836 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 11156 T3836 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C398 name=collection1 org.apache.solr.core.SolrCore@16fc984 url=http://127.0.0.1:54391/collection1 node=127.0.0.1:54391_ C398_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:54391_, base_url=http://127.0.0.1:54391}
[junit4:junit4]   2> 11157 T3838 C398 P54391 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 11158 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 11159 T3836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11159 T3838 C398 P54391 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 11159 T3838 C398 P54391 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11160 T3777 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 11160 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 11161 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11163 T3838 C398 P54391 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11169 T3777 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C399 name=collection1 org.apache.solr.core.SolrCore@1fecf0 url=http://127.0.0.1:54370/collection1 node=127.0.0.1:54370_ C399_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:54370_, base_url=http://127.0.0.1:54370, leader=true}
[junit4:junit4]   2> 11183 T3794 C399 P54370 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df0b15 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15bf462),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11183 T3794 C399 P54370 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11186 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[1 (1429974734015037440)]} 0 6
[junit4:junit4]   2> 11186 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10001 (1429974734013988864)]} 0 8
[junit4:junit4]   2> ASYNC  NEW_CORE C400 name=collection1 org.apache.solr.core.SolrCore@8e7fa2 url=http://127.0.0.1:54382/collection1 node=127.0.0.1:54382_ C400_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54382_, base_url=http://127.0.0.1:54382, leader=true}
[junit4:junit4]   2> 11201 T3815 C400 P54382 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40e710 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b123e9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11201 T3815 C400 P54382 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11204 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[1 (1429974734036008960)]} 0 5
[junit4:junit4]   2> 11204 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10001 (1429974734032863232)]} 0 7
[junit4:junit4]   2> 11225 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[2 (1429974734062223360)]} 0 1
[junit4:junit4]   2> 11226 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10002 (1429974734062223361)]} 0 1
[junit4:junit4]   2> 11234 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[2 (1429974734064320512)]} 0 7
[junit4:junit4]   2> 11235 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10002 (1429974734065369088)]} 0 7
[junit4:junit4]   2> 11266 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[3 (1429974734104166400)]} 0 1
[junit4:junit4]   2> 11267 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10003 (1429974734106263552)]} 0 0
[junit4:junit4]   2> 11268 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[3 (1429974734107312128)]} 0 0
[junit4:junit4]   2> 11270 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10003 (1429974734109409280)]} 0 0
[junit4:junit4]   2> 11280 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[2 (-1429974734119895040)]} 0 0
[junit4:junit4]   2> 11283 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[10002 (-1429974734123040768)]} 0 0
[junit4:junit4]   2> 11283 T3815 C400 P54382 /update {wt=javabin&version=2} {delete=[2 (-1429974734123040768)]} 0 0
[junit4:junit4]   2> 11285 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10002 (-1429974734125137920)]} 0 0
[junit4:junit4]   2> 11286 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[4 (1429974734125137920)]} 0 1
[junit4:junit4]   2> 11288 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10004 (1429974734127235072)]} 0 1
[junit4:junit4]   2> 11288 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[4 (1429974734128283648)]} 0 0
[junit4:junit4]   2> 11291 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10004 (1429974734130380800)]} 0 1
[junit4:junit4]   2> 11346 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[5 (1429974734189101056)]} 0 0
[junit4:junit4]   2> 11348 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10005 (1429974734191198208)]} 0 0
[junit4:junit4]   2> 11349 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[5 (1429974734192246784)]} 0 0
[junit4:junit4]   2> 11351 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10005 (1429974734194343936)]} 0 0
[junit4:junit4]   2> 11380 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[3 (-1429974734224752640)]} 0 0
[junit4:junit4]   2> 11382 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[10003 (-1429974734226849792)]} 0 0
[junit4:junit4]   2> 11382 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[3 (-1429974734226849792)]} 0 0
[junit4:junit4]   2> 11385 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[10003 (-1429974734229995520)]} 0 0
[junit4:junit4]   2> 11385 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[6 (1429974734229995520)]} 0 0
[junit4:junit4]   2> 11388 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10006 (1429974734232092672)]} 0 1
[junit4:junit4]   2> 11388 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[6 (1429974734233141248)]} 0 0
[junit4:junit4]   2> 11389 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10006 (1429974734234189824)]} 0 0
[junit4:junit4]   2> 11440 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[4 (-1429974734287667200)]} 0 0
[junit4:junit4]   2> 11442 T3793 C399 P54370 /update {wt=javabin&version=2} {delete=[10004 (-1429974734289764352)]} 0 0
[junit4:junit4]   2> 11443 T3815 C400 P54382 /update {wt=javabin&version=2} {delete=[4 (-1429974734290812928)]} 0 0
[junit4:junit4]   2> 11444 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10004 (-1429974734291861504)]} 0 0
[junit4:junit4]   2> 11445 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[7 (1429974734292910080)]} 0 0
[junit4:junit4]   2> 11447 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10007 (1429974734295007232)]} 0 0
[junit4:junit4]   2> 11449 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[7 (1429974734297104384)]} 0 0
[junit4:junit4]   2> 11450 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10007 (1429974734297104385)]} 0 1
[junit4:junit4]   2> 11455 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[8 (1429974734303395840)]} 0 0
[junit4:junit4]   2> 11456 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10008 (1429974734304444416)]} 0 0
[junit4:junit4]   2> 11457 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[8 (1429974734305492992)]} 0 0
[junit4:junit4]   2> 11458 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10008 (1429974734306541568)]} 0 0
[junit4:junit4]   2> 11536 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[6 (-1429974734388330496)]} 0 0
[junit4:junit4]   2> 11537 T3793 C399 P54370 /update {wt=javabin&version=2} {delete=[10006 (-1429974734389379072)]} 0 0
[junit4:junit4]   2> 11539 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[6 (-1429974734391476224)]} 0 0
[junit4:junit4]   2> 11540 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[10006 (-1429974734392524800)]} 0 0
[junit4:junit4]   2> 11541 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[9 (1429974734393573376)]} 0 0
[junit4:junit4]   2> 11543 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10009 (1429974734394621952)]} 0 1
[junit4:junit4]   2> 11543 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[9 (1429974734395670528)]} 0 0
[junit4:junit4]   2> 11544 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10009 (1429974734396719104)]} 0 0
[junit4:junit4]   2> 11557 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10 (1429974734409302016)]} 0 1
[junit4:junit4]   2> 11557 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10010 (1429974734410350592)]} 0 0
[junit4:junit4]   2> 11559 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10 (1429974734412447744)]} 0 0
[junit4:junit4]   2> 11560 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10010 (1429974734413496320)]} 0 0
[junit4:junit4]   2> 11585 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[9 (-1429974734439710720)]} 0 0
[junit4:junit4]   2> 11586 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[10009 (-1429974734440759296)]} 0 0
[junit4:junit4]   2> 11587 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[9 (-1429974734441807872)]} 0 0
[junit4:junit4]   2> 11588 T3810 C400 P54382 /update {wt=javabin&version=2} {delete=[10009 (-1429974734442856448)]} 0 0
[junit4:junit4]   2> 11590 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[11 (1429974734444953600)]} 0 0
[junit4:junit4]   2> 11591 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10011 (1429974734444953601)]} 0 1
[junit4:junit4]   2> 11592 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[11 (1429974734447050752)]} 0 0
[junit4:junit4]   2> 11594 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[10011 (1429974734448099328)]} 0 1
[junit4:junit4]   2> 11627 T3790 C399 P54370 /update {wt=javabin&version=2} {delete=[10 (-1429974734483750912)]} 0 0
[junit4:junit4]   2> 11627 T3793 C399 P54370 /update {wt=javabin&version=2} {delete=[10010 (-1429974734483750913)]} 0 0
[junit4:junit4]   2> 11629 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10 (-1429974734485848064)]} 0 0
[junit4:junit4]   2> 11630 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[10010 (-1429974734486896640)]} 0 0
[junit4:junit4]   2> 11631 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[12 (1429974734487945216)]} 0 0
[junit4:junit4]   2> 11632 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10012 (1429974734488993792)]} 0 0
[junit4:junit4]   2> 11634 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[12 (1429974734491090944)]} 0 0
[junit4:junit4]   2> 11635 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10012 (1429974734491090945)]} 0 0
[junit4:junit4]   2> 11640 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11641 T3800 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:54391_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54391"}
[junit4:junit4]   2> 11650 T3819 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> 11651 T3799 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> 11651 T3806 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> 11651 T3835 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> 11708 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[12 (-1429974734568685568)]} 0 0
[junit4:junit4]   2> 11709 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[10012 (-1429974734569734144)]} 0 0
[junit4:junit4]   2>  C398_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:54391_, base_url=http://127.0.0.1:54391}
[junit4:junit4]   2> 11722 T3826 C398 P54391 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18a9eb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b33),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 11722 T3826 C398 P54391 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 11725 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[12 (-1429974734571831296)]} 0 6
[junit4:junit4]   2> 11725 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10012 (-1429974734571831297)]} 0 3
[junit4:junit4]   2> 11725 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10012 (-1429974734571831297)]} 0 14
[junit4:junit4]   2> 11725 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[12 (-1429974734571831296)]} 0 14
[junit4:junit4]   2> 11728 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[13 (1429974734589657088)]} 0 0
[junit4:junit4]   2> 11728 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10013 (1429974734589657089)]} 0 0
[junit4:junit4]   2> 11734 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1429974734591754240)]} 0 1
[junit4:junit4]   2> 11735 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[13 (1429974734591754240)]} 0 5
[junit4:junit4]   2> 11735 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10013 (1429974734592802816)]} 0 1
[junit4:junit4]   2> 11735 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10013 (1429974734592802816)]} 0 4
[junit4:junit4]   2> 11802 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[14 (1429974734667251712)]} 0 0
[junit4:junit4]   2> 11802 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10014 (1429974734667251713)]} 0 0
[junit4:junit4]   2> 11808 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1429974734670397440)]} 0 2
[junit4:junit4]   2> 11808 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10014 (1429974734670397441)]} 0 1
[junit4:junit4]   2> 11809 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[14 (1429974734670397440)]} 0 4
[junit4:junit4]   2> 11810 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10014 (1429974734670397441)]} 0 5
[junit4:junit4]   2> 11889 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[13 (-1429974734758477824)]} 0 0
[junit4:junit4]   2> 11890 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[10013 (-1429974734759526400)]} 0 0
[junit4:junit4]   2> 11893 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[13 (-1429974734760574976)]} 0 0
[junit4:junit4]   2> 11893 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[13 (-1429974734760574976)]} 0 2
[junit4:junit4]   2> 11895 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10013 (-1429974734762672128)]} 0 0
[junit4:junit4]   2> 11896 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[10013 (-1429974734762672128)]} 0 3
[junit4:junit4]   2> 11896 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[15 (1429974734764769280)]} 0 1
[junit4:junit4]   2> 11898 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10015 (1429974734766866432)]} 0 1
[junit4:junit4]   2> 11901 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1429974734767915008)]} 0 1
[junit4:junit4]   2> 11901 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[15 (1429974734767915008)]} 0 3
[junit4:junit4]   2> 11902 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10015 (1429974734770012160)]} 0 0
[junit4:junit4]   2> 11903 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10015 (1429974734770012160)]} 0 3
[junit4:junit4]   2> 11961 T3814 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=3&state=recovering&nodeName=127.0.0.1:54391_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=791 
[junit4:junit4]   2> 11971 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[14 (-1429974734844461056)]} 0 0
[junit4:junit4]   2> 11971 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[10014 (-1429974734844461057)]} 0 0
[junit4:junit4]   2> 11974 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10014 (-1429974734846558208)]} 0 0
[junit4:junit4]   2> 11974 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[14 (-1429974734846558209)]} 0 0
[junit4:junit4]   2> 11975 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10014 (-1429974734846558208)]} 0 2
[junit4:junit4]   2> 11977 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[14 (-1429974734846558209)]} 0 4
[junit4:junit4]   2> 11979 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10016 (1429974734851801088)]} 0 1
[junit4:junit4]   2> 11979 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[16 (1429974734851801089)]} 0 1
[junit4:junit4]   2> 11984 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10016 (1429974734854946816)]} 0 1
[junit4:junit4]   2> 11984 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10016 (1429974734854946816)]} 0 3
[junit4:junit4]   2> 11984 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1429974734854946817)]} 0 0
[junit4:junit4]   2> 11985 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[16 (1429974734854946817)]} 0 4
[junit4:junit4]   2> 12050 T3790 C399 P54370 /update {wt=javabin&version=2} {delete=[10016 (-1429974734927298560)]} 0 0
[junit4:junit4]   2> 12051 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[16 (-1429974734928347136)]} 0 0
[junit4:junit4]   2> 12054 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10016 (-1429974734929395712)]} 0 0
[junit4:junit4]   2> 12055 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[16 (-1429974734930444288)]} 0 0
[junit4:junit4]   2> 12055 T3814 C400 P54382 /update {wt=javabin&version=2} {delete=[10016 (-1429974734929395712)]} 0 3
[junit4:junit4]   2> 12055 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[16 (-1429974734930444288)]} 0 2
[junit4:junit4]   2> 12058 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10017 (1429974734934638592)]} 0 1
[junit4:junit4]   2> 12058 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[17 (1429974734935687168)]} 0 0
[junit4:junit4]   2> 12062 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10017 (1429974734936735744)]} 0 0
[junit4:junit4]   2> 12063 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1429974734937784320)]} 0 1
[junit4:junit4]   2> 12064 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10017 (1429974734936735744)]} 0 4
[junit4:junit4]   2> 12064 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[17 (1429974734937784320)]} 0 4
[junit4:junit4]   2> 12084 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10018 (1429974734961901568)]} 0 1
[junit4:junit4]   2> 12085 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[18 (1429974734962950144)]} 0 1
[junit4:junit4]   2> 12089 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1429974734965047296)]} 0 0
[junit4:junit4]   2> 12090 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1429974734965047297)]} 0 1
[junit4:junit4]   2> 12090 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10018 (1429974734965047296)]} 0 4
[junit4:junit4]   2> 12091 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[18 (1429974734965047297)]} 0 5
[junit4:junit4]   2> 12132 T3790 C399 P54370 /update {wt=javabin&version=2} {delete=[10018 (-1429974735013281792)]} 0 0
[junit4:junit4]   2> 12133 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[18 (-1429974735014330368)]} 0 0
[junit4:junit4]   2> 12136 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10018 (-1429974735016427520)]} 0 0
[junit4:junit4]   2> 12137 T3814 C400 P54382 /update {wt=javabin&version=2} {delete=[10018 (-1429974735016427520)]} 0 2
[junit4:junit4]   2> 12137 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[18 (-1429974735017476096)]} 0 0
[junit4:junit4]   2> 12138 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[18 (-1429974735017476096)]} 0 2
[junit4:junit4]   2> 12140 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10019 (1429974735020621824)]} 0 1
[junit4:junit4]   2> 12141 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[19 (1429974735022718976)]} 0 0
[junit4:junit4]   2> 12144 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1429974735023767552)]} 0 0
[junit4:junit4]   2> 12146 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10019 (1429974735023767552)]} 0 4
[junit4:junit4]   2> 12146 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1429974735024816128)]} 0 0
[junit4:junit4]   2> 12146 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[19 (1429974735024816128)]} 0 3
[junit4:junit4]   2> 12204 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[10019 (-1429974735088779264)]} 0 0
[junit4:junit4]   2> 12205 T3793 C399 P54370 /update {wt=javabin&version=2} {delete=[19 (-1429974735089827840)]} 0 0
[junit4:junit4]   2> 12209 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[19 (-1429974735091924993)]} 0 0
[junit4:junit4]   2> 12209 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10019 (-1429974735091924992)]} 0 0
[junit4:junit4]   2> 12210 T3815 C400 P54382 /update {wt=javabin&version=2} {delete=[19 (-1429974735091924993)]} 0 3
[junit4:junit4]   2> 12210 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10019 (-1429974735091924992)]} 0 3
[junit4:junit4]   2> 12213 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[10020 (1429974735097167873)]} 0 1
[junit4:junit4]   2> 12213 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[20 (1429974735097167872)]} 0 1
[junit4:junit4]   2> 12217 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1429974735099265024)]} 0 1
[junit4:junit4]   2> 12217 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1429974735100313600)]} 0 0
[junit4:junit4]   2> 12218 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10020 (1429974735099265024)]} 0 4
[junit4:junit4]   2> 12219 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[20 (1429974735100313600)]} 0 4
[junit4:junit4]   2> 12273 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10021 (1429974735160082432)]} 0 1
[junit4:junit4]   2> 12273 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[21 (1429974735161131008)]} 0 0
[junit4:junit4]   2> 12278 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1429974735163228161)]} 0 1
[junit4:junit4]   2> 12278 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1429974735163228160)]} 0 1
[junit4:junit4]   2> 12279 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[21 (1429974735163228161)]} 0 4
[junit4:junit4]   2> 12279 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10021 (1429974735163228160)]} 0 4
[junit4:junit4]   2> 12309 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[22 (1429974735197831169)]} 0 1
[junit4:junit4]   2> 12309 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10022 (1429974735197831168)]} 0 1
[junit4:junit4]   2> 12314 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1429974735200976896)]} 0 0
[junit4:junit4]   2> 12314 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1429974735200976897)]} 0 0
[junit4:junit4]   2> 12315 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10022 (1429974735200976896)]} 0 4
[junit4:junit4]   2> 12315 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[22 (1429974735200976897)]} 0 4
[junit4:junit4]   2> 12342 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[10023 (1429974735232434176)]} 0 1
[junit4:junit4]   2> 12342 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[23 (1429974735233482752)]} 0 0
[junit4:junit4]   2> 12348 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1429974735235579904)]} 0 1
[junit4:junit4]   2> 12348 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1429974735235579905)]} 0 1
[junit4:junit4]   2> 12348 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10023 (1429974735235579904)]} 0 4
[junit4:junit4]   2> 12349 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[23 (1429974735235579905)]} 0 5
[junit4:junit4]   2> 12422 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10024 (1429974735317368832)]} 0 0
[junit4:junit4]   2> 12423 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[24 (1429974735317368833)]} 0 1
[junit4:junit4]   2> 12426 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1429974735320514560)]} 0 0
[junit4:junit4]   2> 12427 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10024 (1429974735320514560)]} 0 2
[junit4:junit4]   2> 12427 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1429974735320514561)]} 0 0
[junit4:junit4]   2> 12428 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[24 (1429974735320514561)]} 0 3
[junit4:junit4]   2> 12474 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10025 (1429974735370846208)]} 0 1
[junit4:junit4]   2> 12474 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[25 (1429974735371894784)]} 0 0
[junit4:junit4]   2> 12479 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1429974735373991936)]} 0 0
[junit4:junit4]   2> 12479 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[25 (1429974735373991936)]} 0 3
[junit4:junit4]   2> 12479 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1429974735373991937)]} 0 0
[junit4:junit4]   2> 12480 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10025 (1429974735373991937)]} 0 4
[junit4:junit4]   2> 12525 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[26 (1429974735424323584)]} 0 1
[junit4:junit4]   2> 12526 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10026 (1429974735426420736)]} 0 0
[junit4:junit4]   2> 12530 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1429974735427469312)]} 0 0
[junit4:junit4]   2> 12531 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1429974735428517888)]} 0 1
[junit4:junit4]   2> 12531 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[26 (1429974735427469312)]} 0 4
[junit4:junit4]   2> 12531 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10026 (1429974735428517888)]} 0 3
[junit4:junit4]   2> 12602 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[27 (1429974735505063936)]} 0 1
[junit4:junit4]   2> 12602 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10027 (1429974735505063937)]} 0 1
[junit4:junit4]   2> 12606 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1429974735508209664)]} 0 0
[junit4:junit4]   2> 12607 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1429974735508209665)]} 0 1
[junit4:junit4]   2> 12607 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[10027 (1429974735508209665)]} 0 3
[junit4:junit4]   2> 12607 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[27 (1429974735508209664)]} 0 3
[junit4:junit4]   2> 12670 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[28 (1429974735576367105)]} 0 1
[junit4:junit4]   2> 12670 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[10028 (1429974735576367104)]} 0 1
[junit4:junit4]   2> 12674 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1429974735578464256)]} 0 0
[junit4:junit4]   2> 12675 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[28 (1429974735578464256)]} 0 4
[junit4:junit4]   2> 12676 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1429974735579512832)]} 0 1
[junit4:junit4]   2> 12677 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10028 (1429974735579512832)]} 0 5
[junit4:junit4]   2> 12750 T3777 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 54391
[junit4:junit4]   2> 12750 T3777 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=13703829
[junit4:junit4]   2> 12754 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[29 (1429974735665496064)]} 0 0
[junit4:junit4]   2> 12756 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10029 (1429974735666544640)]} 0 1
[junit4:junit4]   2> 12759 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1429974735668641792)]} 0 0
[junit4:junit4]   2> 12760 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[29 (1429974735668641792)]} 0 3
[junit4:junit4]   2> 12761 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1429974735670738944)]} 0 0
[junit4:junit4]   2> 12762 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10029 (1429974735670738944)]} 0 3
[junit4:junit4]   2> 12826 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[30 (1429974735740993536)]} 0 0
[junit4:junit4]   2> 12828 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10030 (1429974735743090688)]} 0 0
[junit4:junit4]   2> 12832 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1429974735745187840)]} 0 0
[junit4:junit4]   2> 12832 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1429974735744139264)]} 0 0
[junit4:junit4]   2> 12833 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10030 (1429974735745187840)]} 0 3
[junit4:junit4]   2> 12833 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[30 (1429974735744139264)]} 0 4
[junit4:junit4]   2> 12842 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12843 T3800 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:54391_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54391"}
[junit4:junit4]   2> 12850 T3806 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> 12850 T3835 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> 12850 T3799 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> 12850 T3819 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> 12865 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[28 (-1429974735781888000)]} 0 0
[junit4:junit4]   2> 12865 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[10028 (-1429974735781888001)]} 0 0
[junit4:junit4]   2> 12867 T3815 C400 P54382 /update {wt=javabin&version=2} {delete=[28 (-1429974735783985152)]} 0 0
[junit4:junit4]   2> 12867 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10028 (-1429974735783985153)]} 0 0
[junit4:junit4]   2> 12870 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[31 (1429974735787130880)]} 0 0
[junit4:junit4]   2> 12870 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10031 (1429974735787130881)]} 0 0
[junit4:junit4]   2> 12872 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10031 (1429974735789228032)]} 0 0
[junit4:junit4]   2> 12873 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[31 (1429974735789228033)]} 0 1
[junit4:junit4]   2> 12940 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[10030 (-1429974735860531200)]} 0 0
[junit4:junit4]   2> 12940 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[30 (-1429974735860531201)]} 0 0
[junit4:junit4]   2> 12943 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10030 (-1429974735863676928)]} 0 0
[junit4:junit4]   2> 12943 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[30 (-1429974735863676929)]} 0 0
[junit4:junit4]   2> 12944 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10032 (1429974735864725504)]} 0 0
[junit4:junit4]   2> 12945 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[32 (1429974735865774080)]} 0 0
[junit4:junit4]   2> 12947 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10032 (1429974735867871232)]} 0 0
[junit4:junit4]   2> 12947 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[32 (1429974735867871233)]} 0 0
[junit4:junit4]   2> 13021 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[33 (1429974735945465856)]} 0 0
[junit4:junit4]   2> 13021 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10033 (1429974735945465857)]} 0 0
[junit4:junit4]   2> 13024 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10033 (1429974735948611584)]} 0 0
[junit4:junit4]   2> 13024 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[33 (1429974735948611585)]} 0 0
[junit4:junit4]   2> 13033 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10034 (1429974735958048768)]} 0 0
[junit4:junit4]   2> 13033 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[34 (1429974735958048769)]} 0 0
[junit4:junit4]   2> 13042 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[10034 (1429974735966437377)]} 0 1
[junit4:junit4]   2> 13042 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[34 (1429974735966437376)]} 0 1
[junit4:junit4]   2> 13104 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10035 (1429974736030400512)]} 0 2
[junit4:junit4]   2> 13104 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[35 (1429974736032497664)]} 0 1
[junit4:junit4]   2> 13106 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10035 (1429974736034594817)]} 0 0
[junit4:junit4]   2> 13107 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[35 (1429974736034594816)]} 0 1
[junit4:junit4]   2> 13127 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[10036 (1429974736055566336)]} 0 1
[junit4:junit4]   2> 13127 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[36 (1429974736056614912)]} 0 0
[junit4:junit4]   2> 13129 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[36 (1429974736058712064)]} 0 0
[junit4:junit4]   2> 13130 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10036 (1429974736058712065)]} 0 1
[junit4:junit4]   2> 13132 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[37 (1429974736061857792)]} 0 0
[junit4:junit4]   2> 13132 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[10037 (1429974736061857793)]} 0 0
[junit4:junit4]   2> 13134 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[37 (1429974736063954944)]} 0 0
[junit4:junit4]   2> 13135 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[10037 (1429974736065003520)]} 0 0
[junit4:junit4]   2> 13211 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[38 (1429974736143646720)]} 0 1
[junit4:junit4]   2> 13212 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10038 (1429974736144695296)]} 0 0
[junit4:junit4]   2> 13213 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[38 (1429974736146792448)]} 0 0
[junit4:junit4]   2> 13214 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10038 (1429974736146792449)]} 0 1
[junit4:junit4]   2> 13244 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[39 (1429974736179298304)]} 0 0
[junit4:junit4]   2> 13246 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10039 (1429974736181395456)]} 0 0
[junit4:junit4]   2> 13247 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[39 (1429974736182444032)]} 0 0
[junit4:junit4]   2> 13248 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10039 (1429974736183492608)]} 0 0
[junit4:junit4]   2> 13304 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[38 (-1429974736242212864)]} 0 0
[junit4:junit4]   2> 13305 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[10038 (-1429974736243261440)]} 0 0
[junit4:junit4]   2> 13307 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[38 (-1429974736245358592)]} 0 0
[junit4:junit4]   2> 13307 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10038 (-1429974736245358593)]} 0 0
[junit4:junit4]   2> 13309 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[40 (1429974736247455744)]} 0 0
[junit4:junit4]   2> 13311 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10040 (1429974736248504320)]} 0 1
[junit4:junit4]   2> 13311 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[40 (1429974736249552896)]} 0 0
[junit4:junit4]   2> 13312 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10040 (1429974736250601472)]} 0 0
[junit4:junit4]   2> 13383 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[41 (1429974736325050368)]} 0 0
[junit4:junit4]   2> 13384 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10041 (1429974736325050369)]} 0 1
[junit4:junit4]   2> 13385 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10041 (1429974736327147520)]} 0 0
[junit4:junit4]   2> 13385 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[41 (1429974736327147521)]} 0 0
[junit4:junit4]   2> 13441 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[40 (-1429974736385867777)]} 0 0
[junit4:junit4]   2> 13441 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[10040 (-1429974736385867776)]} 0 0
[junit4:junit4]   2> 13444 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[40 (-1429974736389013504)]} 0 0
[junit4:junit4]   2> 13444 T3810 C400 P54382 /update {wt=javabin&version=2} {delete=[10040 (-1429974736389013505)]} 0 0
[junit4:junit4]   2> 13447 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[42 (1429974736391110657)]} 0 1
[junit4:junit4]   2> 13447 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10042 (1429974736391110656)]} 0 1
[junit4:junit4]   2> 13449 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10042 (1429974736394256384)]} 0 0
[junit4:junit4]   2> 13449 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[42 (1429974736394256385)]} 0 0
[junit4:junit4]   2> 13472 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10043 (1429974736417325056)]} 0 1
[junit4:junit4]   2> 13472 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[43 (1429974736417325057)]} 0 1
[junit4:junit4]   2> 13473 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10043 (1429974736419422208)]} 0 0
[junit4:junit4]   2> 13474 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[43 (1429974736420470784)]} 0 0
[junit4:junit4]   2> 13536 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[10041 (-1429974736485482496)]} 0 0
[junit4:junit4]   2> 13536 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[41 (-1429974736485482497)]} 0 0
[junit4:junit4]   2> 13538 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10041 (-1429974736487579648)]} 0 0
[junit4:junit4]   2> 13539 T3810 C400 P54382 /update {wt=javabin&version=2} {delete=[41 (-1429974736488628224)]} 0 0
[junit4:junit4]   2> 13541 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10044 (1429974736489676800)]} 0 1
[junit4:junit4]   2> 13541 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[44 (1429974736490725376)]} 0 0
[junit4:junit4]   2> 13543 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10044 (1429974736492822528)]} 0 0
[junit4:junit4]   2> 13543 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[44 (1429974736492822529)]} 0 0
[junit4:junit4]   2>  C398_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:54391_, base_url=http://127.0.0.1:54391}
[junit4:junit4]   2> 13548 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54382/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 13548 T3838 C398 P54391 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54391 START replicas=[http://127.0.0.1:54382/collection1/] nUpdates=100
[junit4:junit4]   2> 13548 T3838 C398 P54391 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 13549 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 13549 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 13549 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 13549 T3838 C398 P54391 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\jetty2\tlog\tlog.0000000000000000000 refcount=1}}
[junit4:junit4]   2> 13550 T3838 C398 P54391 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54382/collection1/. core=collection1
[junit4:junit4]   2> 13550 T3838 C398 P54391 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13550 T3814 C400 P54382 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 13554 T3815 C400 P54382 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 13556 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[45 (1429974736506454016)]} 0 0
[junit4:junit4]   2> 13558 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10045 (1429974736508551168)]} 0 0
[junit4:junit4]   2> 13559 T3815 C400 P54382 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40e710 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b123e9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@40e710 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b123e9),segFN=segments_2,generation=2,filenames=[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, segments_2, _0_Direct_0.tip, _0.fdx, _0.si, _0_Direct_0.tim, _0.fdt]
[junit4:junit4]   2> 13560 T3815 C400 P54382 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, segments_2, _0_Direct_0.tip, _0.fdx, _0.si, _0_Direct_0.tim, _0.fdt]
[junit4:junit4]   2> 13563 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10045 (1429974736510648321)]} 0 3
[junit4:junit4]   2> 13563 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[45 (1429974736510648320)]} 0 3
[junit4:junit4]   2> 13566 T3815 C400 P54382 oass.SolrIndexSearcher.<init> Opening Searcher@c25043 realtime
[junit4:junit4]   2> 13567 T3815 C400 P54382 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 13567 T3815 C400 P54382 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4]   2> 13568 T3838 C398 P54391 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 13568 T3838 C398 P54391 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 13570 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10046 (1429974736521134080)]} 0 0
[junit4:junit4]   2> 13570 T3812 C400 P54382 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 13570 T3812 C400 P54382 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 13570 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[46 (1429974736521134081)]} 0 0
[junit4:junit4]   2> 13571 T3838 C398 P54391 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 13571 T3838 C398 P54391 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 13571 T3838 C398 P54391 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 13573 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10046 (1429974736523231232)]} 0 1
[junit4:junit4]   2> 13573 T3810 C400 P54382 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0 
[junit4:junit4]   2> 13573 T3838 C398 P54391 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 24
[junit4:junit4]   2> 13573 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[46 (1429974736524279808)]} 0 0
[junit4:junit4]   2> 13574 T3838 C398 P54391 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\index.20130320115619333 forceNew: false
[junit4:junit4]   2> 13574 T3838 C398 P54391 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e) fullCopy=true
[junit4:junit4]   2> 13576 T3815 C400 P54382 REQ /replication {file=_0_Lucene41WithOrds_0.tib&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13583 T3813 C400 P54382 REQ /replication {file=_0_Lucene41WithOrds_0.tii&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13587 T3812 C400 P54382 REQ /replication {file=_0_Lucene41WithOrds_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13589 T3810 C400 P54382 REQ /replication {file=_0_NestedPulsing_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13592 T3811 C400 P54382 REQ /replication {file=_0_NestedPulsing_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13594 T3814 C400 P54382 REQ /replication {file=_0_NestedPulsing_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13597 T3815 C400 P54382 REQ /replication {file=_0_Pulsing41_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13606 T3813 C400 P54382 REQ /replication {file=_0_Pulsing41_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13608 T3812 C400 P54382 REQ /replication {file=_0.nvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13610 T3810 C400 P54382 REQ /replication {file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13613 T3811 C400 P54382 REQ /replication {file=_0_NestedPulsing_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13616 T3814 C400 P54382 REQ /replication {file=_0_Lucene41WithOrds_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13618 T3815 C400 P54382 REQ /replication {file=_0.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13624 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[10042 (-1429974736577757184)]} 0 0
[junit4:junit4]   2> 13626 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[42 (-1429974736579854336)]} 0 0
[junit4:junit4]   2> 13626 T3813 C400 P54382 REQ /replication {file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13627 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10042 (-1429974736580902912)]} 0 0
[junit4:junit4]   2> 13627 T3810 C400 P54382 /update {wt=javabin&version=2} {delete=[42 (-1429974736580902913)]} 0 0
[junit4:junit4]   2> 13628 T3811 C400 P54382 REQ /replication {file=_0.nvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13630 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10047 (1429974736583000064)]} 0 1
[junit4:junit4]   2> 13630 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[47 (1429974736584048640)]} 0 0
[junit4:junit4]   2> 13631 T3814 C400 P54382 REQ /replication {file=_0_Direct_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13632 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10047 (1429974736585097216)]} 0 1
[junit4:junit4]   2> 13633 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[47 (1429974736587194368)]} 0 0
[junit4:junit4]   2> 13634 T3813 C400 P54382 REQ /replication {file=_0_Pulsing41_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13636 T3810 C400 P54382 REQ /replication {file=_0_Pulsing41_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13638 T3811 C400 P54382 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13647 T3814 C400 P54382 REQ /replication {file=_0_Direct_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13651 T3815 C400 P54382 REQ /replication {file=_0.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13655 T3812 C400 P54382 REQ /replication {file=_0_Direct_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13658 T3813 C400 P54382 REQ /replication {file=_0_Direct_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13661 T3810 C400 P54382 REQ /replication {file=_0.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 13661 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[10048 (1429974736616554496)]} 0 0
[junit4:junit4]   2> 13661 T3838 C398 P54391 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 13662 T3838 C398 P54391 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130320115619333
[junit4:junit4]   2> 13662 T3838 C398 P54391 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 13662 T3838 C398 P54391 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 13662 T3838 C398 P54391 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 13663 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[48 (1429974736618651648)]} 0 0
[junit4:junit4]   2> 13663 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[10048 (1429974736618651648)]} 0 0
[junit4:junit4]   2> 13664 T3838 C398 P54391 oasc.SolrCore.getNewIndexDir New index directory detected: old=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\index/ new=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\index.20130320115619333
[junit4:junit4]   2> 13665 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[48 (1429974736620748800)]} 0 0
[junit4:junit4]   2> 13667 T3838 C398 P54391 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e),segFN=segments_2,generation=2,filenames=[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, segments_2, _0.fdx, _0_Direct_0.tip, _0.si, _0_Direct_0.tim, _0.fdt]
[junit4:junit4]   2> 13667 T3838 C398 P54391 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, segments_2, _0.fdx, _0_Direct_0.tip, _0.si, _0_Direct_0.tim, _0.fdt]
[junit4:junit4]   2> 13668 T3838 C398 P54391 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 13668 T3838 C398 P54391 oass.SolrIndexSearcher.<init> Opening Searcher@1639ac3 main
[junit4:junit4]   2> 13675 T3837 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1639ac3 main{StandardDirectoryReader(segments_2:3:nrt _0(4.3):C88/34)}
[junit4:junit4]   2> 13676 T3838 C398 P54391 oash.SnapPuller$2.preClose removing old index files MockDirWrapper(org.apache.lucene.store.RAMDirectory@18a9eb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b33)
[junit4:junit4]   2> 13676 T3838 C398 P54391 oasc.CachingDirectoryFactory.closeDirectory Closing directory: .\org.apache.solr.cloud.RecoveryZkTest-1363730165763/jetty2\index
[junit4:junit4]   2> 13676 T3838 C398 P54391 oash.SnapPuller$2.postClose removing old index directory MockDirWrapper(org.apache.lucene.store.RAMDirectory@18a9eb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b33)
[junit4:junit4]   2> 13677 T3838 C398 P54391 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4]   2> 13677 T3846 C398 P54391 oasu.UpdateLog$LogReplayer.doReplay WARNING Starting log replay tlog{file=.\org.apache.solr.cloud.RecoveryZkTest-1363730165763\jetty2\tlog\tlog.0000000000000000000 refcount=2} active=true starting pos=5109
[junit4:junit4]   2> 13677 T3846 C398 P54391 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 13678 T3846 C398 P54391 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e),segFN=segments_2,generation=2,filenames=[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, segments_2, _0.fdx, _0_Direct_0.tip, _0.si, _0_Direct_0.tim, _0.fdt]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e),segFN=segments_3,generation=3,filenames=[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, _0.fdx, _0_Direct_0.tip, _0.si, _0_Direct_0.tim, _0.fdt, segments_3]
[junit4:junit4]   2> 13678 T3846 C398 P54391 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, _0.fdx, _0_Direct_0.tip, _0.si, _0_Direct_0.tim, _0.fdt, segments_3]
[junit4:junit4]   2> 13678 T3846 C398 P54391 oass.SolrIndexSearcher.<init> Opening Searcher@d2b272 main
[junit4:junit4]   2> 13678 T3846 C398 P54391 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 13678 T3837 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d2b272 main{StandardDirectoryReader(segments_2:3:nrt _0(4.3):C88/34)}
[junit4:junit4]   2> 13679 T3846 C398 P54391 oasu.UpdateLog$LogReplayer.run WARNING Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=5109}
[junit4:junit4]   2> 13679 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 13679 T3838 C398 P54391 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 13680 T3838 C398 P54391 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 13682 T3838 C398 P54391 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 13734 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[10043 (-1429974736693100544)]} 0 0
[junit4:junit4]   2> 13735 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[43 (-1429974736694149120)]} 0 0
[junit4:junit4]   2> 13737 T3815 C400 P54382 /update {wt=javabin&version=2} {delete=[10043 (-1429974736696246272)]} 0 0
[junit4:junit4]   2> 13738 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[43 (-1429974736697294848)]} 0 0
[junit4:junit4]   2> 13739 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10049 (1429974736698343424)]} 0 0
[junit4:junit4]   2> 13741 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[49 (1429974736699392000)]} 0 1
[junit4:junit4]   2> 13742 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10049 (1429974736701489152)]} 0 0
[junit4:junit4]   2> 13742 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[49 (1429974736701489153)]} 0 0
[junit4:junit4]   2> 13763 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[10044 (-1429974736723509248)]} 0 0
[junit4:junit4]   2> 13764 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[44 (-1429974736724557824)]} 0 0
[junit4:junit4]   2> 13765 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10044 (-1429974736725606400)]} 0 0
[junit4:junit4]   2> 13766 T3814 C400 P54382 /update {wt=javabin&version=2} {delete=[44 (-1429974736726654976)]} 0 0
[junit4:junit4]   2> 13768 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10050 (1429974736728752128)]} 0 0
[junit4:junit4]   2> 13769 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[50 (1429974736729800704)]} 0 0
[junit4:junit4]   2> 13770 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[10050 (1429974736730849280)]} 0 0
[junit4:junit4]   2> 13771 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[50 (1429974736731897856)]} 0 0
[junit4:junit4]   2> 13821 T3793 C399 P54370 /update {wt=javabin&version=2} {delete=[10046 (-1429974736784326656)]} 0 0
[junit4:junit4]   2> 13822 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[46 (-1429974736785375232)]} 0 0
[junit4:junit4]   2> 13823 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10046 (-1429974736786423808)]} 0 0
[junit4:junit4]   2> 13824 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[46 (-1429974736787472384)]} 0 0
[junit4:junit4]   2> 13826 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10051 (1429974736789569536)]} 0 0
[junit4:junit4]   2> 13826 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[51 (1429974736789569537)]} 0 0
[junit4:junit4]   2> 13829 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10051 (1429974736791666688)]} 0 1
[junit4:junit4]   2> 13829 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[51 (1429974736792715264)]} 0 0
[junit4:junit4]   2> 13864 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[10047 (-1429974736829415424)]} 0 0
[junit4:junit4]   2> 13866 T3790 C399 P54370 /update {wt=javabin&version=2} {delete=[47 (-1429974736831512576)]} 0 0
[junit4:junit4]   2> 13866 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[10047 (-1429974736831512576)]} 0 0
[junit4:junit4]   2> 13868 T3810 C400 P54382 /update {wt=javabin&version=2} {delete=[47 (-1429974736833609728)]} 0 0
[junit4:junit4]   2> 13870 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10052 (1429974736834658304)]} 0 1
[junit4:junit4]   2> 13870 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[52 (1429974736835706880)]} 0 0
[junit4:junit4]   2> 13871 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10052 (1429974736836755456)]} 0 0
[junit4:junit4]   2> 13873 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[52 (1429974736838852608)]} 0 0
[junit4:junit4]   2> 13927 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10053 (1429974736895475712)]} 0 0
[junit4:junit4]   2> 13929 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[53 (1429974736897572864)]} 0 0
[junit4:junit4]   2> 13930 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10053 (1429974736898621440)]} 0 0
[junit4:junit4]   2> 13932 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[53 (1429974736900718592)]} 0 0
[junit4:junit4]   2> 13948 T3795 C399 P54370 /update {wt=javabin&version=2} {delete=[10050 (-1429974736917495808)]} 0 0
[junit4:junit4]   2> 13950 T3790 C399 P54370 /update {wt=javabin&version=2} {delete=[50 (-1429974736919592960)]} 0 0
[junit4:junit4]   2> 13950 T3812 C400 P54382 /update {wt=javabin&version=2} {delete=[10050 (-1429974736919592960)]} 0 0
[junit4:junit4]   2> 13952 T3810 C400 P54382 /update {wt=javabin&version=2} {delete=[50 (-1429974736921690112)]} 0 0
[junit4:junit4]   2> 13954 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10054 (1429974736922738688)]} 0 1
[junit4:junit4]   2> 13954 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[54 (1429974736923787264)]} 0 0
[junit4:junit4]   2> 13956 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10054 (1429974736925884416)]} 0 0
[junit4:junit4]   2> 13957 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[54 (1429974736926932992)]} 0 0
[junit4:junit4]   2> 14009 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[10052 (-1429974736981458944)]} 0 0
[junit4:junit4]   2> 14011 T3794 C399 P54370 /update {wt=javabin&version=2} {delete=[52 (-1429974736983556096)]} 0 0
[junit4:junit4]   2> 14011 T3814 C400 P54382 /update {wt=javabin&version=2} {delete=[10052 (-1429974736983556096)]} 0 0
[junit4:junit4]   2> 14012 T3815 C400 P54382 /update {wt=javabin&version=2} {delete=[52 (-1429974736984604672)]} 0 0
[junit4:junit4]   2> 14014 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10055 (1429974736986701824)]} 0 0
[junit4:junit4]   2> 14015 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[55 (1429974736986701825)]} 0 1
[junit4:junit4]   2> 14016 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10055 (1429974736988798976)]} 0 0
[junit4:junit4]   2> 14017 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[55 (1429974736989847552)]} 0 0
[junit4:junit4]   2> 14023 T3793 C399 P54370 /update {wt=javabin&version=2} {delete=[10053 (-1429974736996139008)]} 0 0
[junit4:junit4]   2> 14024 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[53 (-1429974736997187584)]} 0 0
[junit4:junit4]   2> 14025 T3813 C400 P54382 /update {wt=javabin&version=2} {delete=[10053 (-1429974736998236160)]} 0 0
[junit4:junit4]   2> 14026 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[53 (-1429974736999284736)]} 0 0
[junit4:junit4]   2> 14028 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10056 (1429974737001381888)]} 0 0
[junit4:junit4]   2> 14028 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[56 (1429974737001381889)]} 0 0
[junit4:junit4]   2> 14030 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10056 (1429974737003479040)]} 0 0
[junit4:junit4]   2> 14031 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[56 (1429974737004527616)]} 0 0
[junit4:junit4]   2> 14042 T3800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14042 T3800 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:54391_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54391"}
[junit4:junit4]   2> 14054 T3806 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> 14054 T3819 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> 14055 T3799 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> 14055 T3835 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> 14106 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10057 (1429974737082122240)]} 0 1
[junit4:junit4]   2> 14106 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[57 (1429974737083170816)]} 0 0
[junit4:junit4]   2>  C398_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:54391_, base_url=http://127.0.0.1:54391}
[junit4:junit4]   2> 14112 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10057 (1429974737085267968)]} 0 3
[junit4:junit4]   2> 14112 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1429974737086316544)]} 0 0
[junit4:junit4]   2> 14113 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10057 (1429974737085267968)]} 0 5
[junit4:junit4]   2> 14113 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[57 (1429974737086316544)]} 0 4
[junit4:junit4]   2> 14124 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[10058 (1429974737102045184)]} 0 0
[junit4:junit4]   2> 14125 T3791 C399 P54370 /update {wt=javabin&version=2} {add=[58 (1429974737103093760)]} 0 0
[junit4:junit4]   2> 14128 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10058 (1429974737104142336)]} 0 0
[junit4:junit4]   2> 14129 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[10058 (1429974737104142336)]} 0 3
[junit4:junit4]   2> 14129 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1429974737105190912)]} 0 0
[junit4:junit4]   2> 14130 T3811 C400 P54382 /update {wt=javabin&version=2} {add=[58 (1429974737105190912)]} 0 3
[junit4:junit4]   2> 14209 T3792 C399 P54370 /update {wt=javabin&version=2} {add=[10059 (1429974737191174144)]} 0 0
[junit4:junit4]   2> 14210 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[59 (1429974737192222720)]} 0 0
[junit4:junit4]   2> 14213 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10059 (1429974737193271296)]} 0 0
[junit4:junit4]   2> 14215 T3814 C400 P54382 /update {wt=javabin&version=2} {add=[10059 (1429974737193271296)]} 0 4
[junit4:junit4]   2> 14215 T3829 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1429974737195368448)]} 0 0
[junit4:junit4]   2> 14216 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[59 (1429974737195368448)]} 0 3
[junit4:junit4]   2> 14277 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10060 (1429974737262477312)]} 0 0
[junit4:junit4]   2> 14277 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[60 (1429974737262477313)]} 0 0
[junit4:junit4]   2> 14281 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10060 (1429974737264574464)]} 0 0
[junit4:junit4]   2> 14281 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1429974737265623040)]} 0 0
[junit4:junit4]   2> 14282 T3812 C400 P54382 /update {wt=javabin&version=2} {add=[10060 (1429974737264574464)]} 0 3
[junit4:junit4]   2> 14282 T3813 C400 P54382 /update {wt=javabin&version=2} {add=[60 (1429974737265623040)]} 0 2
[junit4:junit4]   2> 14327 T3791 C399 P54370 /update {wt=javabin&version=2} {delete=[10054 (-1429974737314906112)]} 0 0
[junit4:junit4]   2> 14327 T3792 C399 P54370 /update {wt=javabin&version=2} {delete=[54 (-1429974737314906113)]} 0 0
[junit4:junit4]   2> 14331 T3831 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[54 (-1429974737317003265)]} 0 0
[junit4:junit4]   2> 14331 T3830 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10054 (-1429974737317003264)]} 0 0
[junit4:junit4]   2> 14332 T3814 C400 P54382 /update {wt=javabin&version=2} {delete=[54 (-1429974737317003265)]} 0 3
[junit4:junit4]   2> 14332 T3811 C400 P54382 /update {wt=javabin&version=2} {delete=[10054 (-1429974737317003264)]} 0 3
[junit4:junit4]   2> 14333 T3777 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14334 T3777 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 14336 T3790 C399 P54370 /update {wt=javabin&version=2} {add=[61 (1429974737324343297)]} 0 0
[junit4:junit4]   2> 14337 T3794 C399 P54370 /update {wt=javabin&version=2} {add=[10061 (1429974737324343296)]} 0 1
[junit4:junit4]   2> 14341 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10061 (1429974737327489024)]} 0 0
[junit4:junit4]   2> 14342 T3827 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1429974737326440448)]} 0 1
[junit4:junit4]   2> 14343 T3810 C400 P54382 /update {wt=javabin&version=2} {add=[10061 (1429974737327489024)]} 0 4
[junit4:junit4]   2> 14343 T3777 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@16fc984
[junit4:junit4]   2> 14344 T3815 C400 P54382 /update {wt=javabin&version=2} {add=[61 (1429974737326440448)]} 0 6
[junit4:junit4]   2> 14357 T3777 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=10,adds=10,deletesById=2,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=14,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 14358 T3777 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 14358 T3777 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 14359 T3777 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 14361 T3795 C399 P54370 /update {wt=javabin&version=2} {add=[10062 (1429974737350557696)]} 0 0
[junit4:junit4]   2> 14361 T3793 C399 P54370 /update {wt=javabin&version=2} {add=[62 (1429974737350557697)]} 0 0
[junit4:junit4]   2> 14364 T3777 C398 P54391 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e),segFN=segments_3,generation=3,filenames=[_0_Lucene41WithOrds_0.tib, _0_NestedPulsing_0.doc, _0.fnm, _0_Lucene41WithOrds_0.doc, _0_1.del, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_Direct_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _0_Direct_0.pos, _0.fdx, _0_Direct_0.tip, _0.si, _0_Direct_0.tim, _0.fdt, segments_3]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e),segFN=segments_4,generation=4,filenames=[_1_Direct_0.pos, _0_Lucene41WithOrds_0.tib, _1_NestedPulsing_0.tip, _1_Direct_0.doc, _1_Lucene41WithOrds_0.doc, _1_Lucene41WithOrds_0.pos, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0_NestedPulsing_0.tip, _1.fnm, _0_NestedPulsing_0.tim, _1_NestedPulsing_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _1_Direct_0.tim, _1_NestedPulsing_0.tim, _0.si, _1_Direct_0.tip, _0_NestedPulsing_0.doc, _1.nvm, _0_Lucene41WithOrds_0.doc, _0.fnm, _1.nvd, _1_NestedPulsing_0.pos, _0_1.del, _1_Pulsing41_0.doc, _0.nvm, _1_Pulsing41_0.pos, _1.fdx, _0_Direct_0.doc, _0_Pulsing41_0.doc, _0_Pulsing41_0.pos, _1_Pulsing41_0.tip, _1.fdt, _1_Pulsing41_0.tim, _1.si, _1_Lucene41WithOrds_0.tii, _1_Lucene41WithOrds_0.tib, _0_Direct_0.pos, _0_Direct_0.tip, _0.fdx, _0_Direct_0.tim, _0.fdt, segments_4]
[junit4:junit4]   2> 14365 T3777 C398 P54391 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_1_Direct_0.pos, _0_Lucene41WithOrds_0.tib, _1_NestedPulsing_0.tip, _1_Direct_0.doc, _1_Lucene41WithOrds_0.doc, _1_Lucene41WithOrds_0.pos, _0_Lucene41WithOrds_0.tii, _0_Lucene41WithOrds_0.pos, _0_NestedPulsing_0.tip, _1.fnm, _0_NestedPulsing_0.tim, _1_NestedPulsing_0.doc, _0_NestedPulsing_0.pos, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0.nvd, _1_Direct_0.tim, _1_NestedPulsing_0.tim, _0.si, _1_Direct_0.tip, _0_NestedPulsing_0.doc, _1.nvm, _0_Lucene41WithOrds_0.doc, _0.fnm, _1.nvd, _1_NestedPulsing_0.pos, _0_1.del, _1_Pulsing41_0.doc, _0.nvm, _1_Pulsing41_0.pos, _1.fdx, _0_Direct_0.doc, _0_Pulsing41_0.doc, _0_Pulsing41_0.pos, _1_Pulsing41_0.tip, _1.fdt, _1_Pulsing41_0.tim, _1.si, _1_Lucene41WithOrds_0.tii, _1_Lucene41WithOrds_0.tib, _0_Direct_0.pos, _0_Direct_0.tip, _0.fdx, _0_Direct_0.tim, _0.fdt, segments_4]
[junit4:junit4]   2> 14365 T3826 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {} 0 0
[junit4:junit4]   2> 14366 T3826 C398 P54391 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:148)
[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:639)
[junit4:junit4]   2> 		at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:345)
[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> 14368 T3826 C398 P54391 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@16fc984
[junit4:junit4]   2> 14368 T3826 C398 P54391 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=10,deletesById=2,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=14,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 14369 T3828 C398 P54391 /update {distrib.from=http://127.0.0.1:54382/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {} 0 0
[junit4:junit4]   2> 14370 T3826 C398 P54391 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 14370 T3777 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 14370 T3828 C398 P54391 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:148)
[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:639)
[junit4:junit4]   2> 		at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:345)
[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> 14371 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100008
[junit4:junit4]   2> 14371 T3812 C400 P54382 oasc.SolrException.log SEVERE shard update error StdNode: http://127.0.0.1:54391/collection1/:org.apache.solr.common.SolrException: Server at http://127.0.0.1:54391/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> 14371 T3828 C398 P54391 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@16fc984
[junit4:junit4]   2> 14372 T3812 C400 P54382 oasup.DistributedUpdateProcessor.doFinish try and ask http://127.0.0.1:54391 to recover
[junit4:junit4]   2> 14372 T3812 C400 P54382 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 14373 T3828 C398 P54391 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=10,deletesById=2,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=14,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 14373 T3828 C398 P54391 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 14375 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54399 which had sessionid 0x13d84a6f0100008
[junit4:junit4]   2> 14375 T3813 C400 P54382 oasc.SolrException.log SEVERE shard update error StdNode: http://127.0.0.1:54391/collection1/:org.apache.solr.common.SolrException: Server at http://127.0.0.1:54391/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> 14375 T3813 C400 P54382 oasup.DistributedUpdateProcessor.doFinish try and ask http://127.0.0.1:54391 to recover
[junit4:junit4]   2> 14376 T3813 C400 P54382 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 14381 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100008 closed
[junit4:junit4]   2> 14381 T3835 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> 14381 T3835 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 14382 T3799 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> 14381 T3806 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 14382 T3806 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> 14382 T3835 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 14383 T3819 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 14383 T3819 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> 14383 T3835 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 14385 T3799 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 14390 T3812 C400 P54382 oahic.DefaultRequestDirector.tryExecute I/O exception (org.apache.http.NoHttpResponseException) caught when processing request: The target server failed to respond
[junit4:junit4]   2> 14390 T3813 C400 P54382 oahic.DefaultRequestDirector.tryExecute I/O exception (org.apache.http.NoHttpResponseException) caught when processing request: The target server failed to respond
[junit4:junit4]   2> 14390 T3812 C400 P54382 oahic.DefaultRequestDirector.tryExecute Retrying request
[junit4:junit4]   2> 14390 T3813 C400 P54382 oahic.DefaultRequestDirector.tryExecute Retrying request
[junit4:junit4]   2> 14391 T3777 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 14600 T3777 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 14604 T3777 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54391
[junit4:junit4]   2> 14604 T3777 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 14610 T3777 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 14611 T3777 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526
[junit4:junit4]   2> 14611 T3777 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\solr.xml
[junit4:junit4]   2> 14612 T3777 oasc.CoreContainer.<init> New CoreContainer 31520284
[junit4:junit4]   2> 14614 T3777 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\'
[junit4:junit4]   2> 14614 T3777 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1363730173526\'
[junit4:junit4]   2> 14654 T3777 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 14655 T3777 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 14655 T3777 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 14655 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 14656 T3777 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 14656 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 14657 T3777 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 14657 T3777 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 14657 T3777 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 14657 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 14667 T3777 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 14693 T3777 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54363/solr
[junit4:junit4]   2> 14694 T3777 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 14694 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3b6e53
[junit4:junit4]   2> 14695 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 14695 T3856 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 14696 T3856 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:54363, initiating session
[junit4:junit4]   2> 14696 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54418
[junit4:junit4]   2> 14697 T3779 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54418
[junit4:junit4]   2> 14698 T3781 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d84a6f0100009 with negotiated timeout 20000 for client /127.0.0.1:54418
[junit4:junit4]   2> 14698 T3856 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:54363, sessionid = 0x13d84a6f0100009, negotiated timeout = 20000
[junit4:junit4]   2> 14698 T3857 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b6e53 name:ZooKeeperConnection Watcher:127.0.0.1:54363 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 14699 T3777 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 14700 T3782 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d84a6f0100009
[junit4:junit4]   2> 14701 T3777 oaz.ZooKeeper.close Session: 0x13d84a6f0100009 closed
[junit4:junit4]   2> 14701 T3777 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 14701 T3857 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 14701 T3779 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54418 which had sessionid 0x13d84a6f0100009
[junit4:junit4]   2> 14705 T3777 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54363/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@80aa82
[junit4:junit4]   2> 14705 T3777 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 14706 T3858 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:54363. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 14707 T3779 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54421
[junit4:junit4]   2>

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

, ZkNodePropsTest, ShardRoutingCustomTest, MultiTermTest, TestCSVLoader, SolrPluginUtilsTest, WordBreakSolrSpellCheckerTest, DirectSolrSpellCheckerTest, OverseerTest, ShardRoutingTest, TestFoldingMultitermQuery, TestElisionMultitermQuery, SchemaVersionSpecificBehaviorTest, DateMathParserTest, TestQuerySenderListener, ChaosMonkeyNothingIsSafeTest, TestSearchPerf, URLClassifyProcessorTest, TestLMDirichletSimilarityFactory, SliceStateUpdateTest, TestSort, TestHashPartitioner, TestRangeQuery, TestUpdate, BasicDistributedZkTest, FastVectorHighlighterTest, TestJoin, PolyFieldTest, TestFastLRUCache, TestBM25SimilarityFactory, HighlighterTest, ClusterStateTest, TestFiltering, TestJmxIntegration, MinimalSchemaTest, TestCollationField, TestSolrJ, FieldMutatingUpdateProcessorTest, BadComponentTest, AutoCommitTest, RegexBoostProcessorTest, ResourceLoaderTest, TestPHPSerializedResponseWriter, TestFieldResource, SuggesterFSTTest, TestPerFieldSimilarity, ExternalFileFieldSortTest, TestFastOutputStream, TestArbitraryIndexDir, TestDocumentBuilder, TestCodecSupport, CoreContainerCoreInitFailuresTest, TestFieldCollectionResource, SimplePostToolTest, QueryParsingTest, TestWordDelimiterFilterFactory, TestReversedWildcardFilterFactory, TestDynamicFieldResource, TestPluginEnable, TestMultiCoreConfBootstrap, TestQueryTypes, TestStressLucene, TestTrie, PathHierarchyTokenizerFactoryTest, TestFaceting, SolrTestCaseJ4Test, SimpleFacetsTest, TestStressRecovery, SampleTest, TestLazyCores, TestUtils, TermsComponentTest, SolrIndexSplitterTest, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, SyncSliceTest, OpenCloseCoreStressTest, LeaderElectionIntegrationTest, BasicZkTest, RecoveryZkTest]
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=RecoveryZkTest -Dtests.seed=76D4303550230D42 -Dtests.slow=true -Dtests.locale=ar_SY -Dtests.timezone=Pacific/Kiritimati -Dtests.file.encoding=Cp1252
[junit4:junit4] ERROR   0.00s | RecoveryZkTest (suite) <<<
[junit4:junit4]    > Throwable #1: com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=3836, name=coreLoadExecutor-2697-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:37)
[junit4:junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
[junit4:junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
[junit4:junit4]    > 	at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
[junit4:junit4]    > 	at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
[junit4:junit4]    > 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java: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@170f63 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9572b)
[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=3838, 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:37)
[junit4:junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:362)
[junit4:junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:322)
[junit4:junit4]    > 	at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
[junit4:junit4]    > 	at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
[junit4:junit4]    > 	at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
[junit4:junit4]    > 	at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
[junit4:junit4]    > 	at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
[junit4:junit4]    > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@1387a39 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b047e)
[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 in 30.16s, 1 test, 2 errors <<< FAILURES!

[...truncated 398 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:381: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:361: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build.xml:183: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\common-build.xml:449: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:1213: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:877: There were test failures: 273 suites, 1147 tests, 2 suite-level errors, 18 ignored (12 assumptions)

Total time: 62 minutes 32 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.6.0_41 -client -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message