You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/03/05 09:55:15 UTC
[JENKINS] Lucene-Solr-trunk-Windows (32bit/jdk1.6.0_41) - Build #
2619 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2619/
Java: 32bit/jdk1.6.0_41 -client -XX:+UseSerialGC
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=559, name=coreLoadExecutor-479-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=559, name=coreLoadExecutor-479-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:33)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:267)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:223)
at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:733)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:874)
at org.apache.solr.core.CoreContainer.create(CoreContainer.java:957)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:580)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:575)
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@35fcce lockFactory=org.apache.lucene.store.NativeFSLockFactory@1539062)
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=561, 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=561, 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:33)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:267)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:223)
at org.apache.solr.handler.SnapPuller.fetchLatestIndex(SnapPuller.java:383)
at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:281)
at org.apache.solr.cloud.RecoveryStrategy.replicate(RecoveryStrategy.java:153)
at org.apache.solr.cloud.RecoveryStrategy.doRecovery(RecoveryStrategy.java:409)
at org.apache.solr.cloud.RecoveryStrategy.run(RecoveryStrategy.java:223)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2)
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 8331 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 0 T500 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /k/i
[junit4:junit4] 2> 1 T500 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-RecoveryZkTest-1362471904554
[junit4:junit4] 2> 3 T500 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 4 T501 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 5 T501 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 5 T501 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 5 T501 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 6 T501 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 6 T501 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\zookeeper\server1\data\version-2\snapshot.0
[junit4:junit4] 2> 62 T500 oasc.ZkTestServer.run start zk server on port:53430
[junit4:junit4] 2> 62 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1d09ad6
[junit4:junit4] 2> 64 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 66 T506 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 66 T506 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 67 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53433
[junit4:junit4] 2> 67 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53433
[junit4:junit4] 2> 67 T504 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 79 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0000 with negotiated timeout 10000 for client /127.0.0.1:53433
[junit4:junit4] 2> 79 T506 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0000, negotiated timeout = 10000
[junit4:junit4] 2> 80 T507 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d09ad6 name:ZooKeeperConnection Watcher:127.0.0.1:53430 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 80 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 80 T500 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 87 T505 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d39a7652f0000
[junit4:junit4] 2> 92 T502 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:53433 which had sessionid 0x13d39a7652f0000
[junit4:junit4] 2> 92 T507 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 92 T500 oaz.ZooKeeper.close Session: 0x13d39a7652f0000 closed
[junit4:junit4] 2> 94 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1506157
[junit4:junit4] 2> 95 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 97 T508 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 97 T508 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 98 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53436
[junit4:junit4] 2> 98 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53436
[junit4:junit4] 2> 101 T508 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0001, negotiated timeout = 10000
[junit4:junit4] 2> 101 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0001 with negotiated timeout 10000 for client /127.0.0.1:53436
[junit4:junit4] 2> 101 T509 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1506157 name:ZooKeeperConnection Watcher:127.0.0.1:53430/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 102 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 103 T500 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 110 T500 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 114 T500 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 117 T500 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 122 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 122 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 130 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 131 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 134 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 134 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 138 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 138 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 141 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 142 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 144 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 145 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 147 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 148 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 152 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 152 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 155 T500 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 155 T500 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 160 T505 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d39a7652f0001
[junit4:junit4] 2> 160 T500 oaz.ZooKeeper.close Session: 0x13d39a7652f0001 closed
[junit4:junit4] 2> 161 T502 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d39a7652f0001, 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> 161 T502 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:53436 which had sessionid 0x13d39a7652f0001
[junit4:junit4] 2> 162 T509 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 408 T500 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 410 T500 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53437
[junit4:junit4] 2> 411 T500 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 411 T500 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 411 T500 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713
[junit4:junit4] 2> 411 T500 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713\solr.xml
[junit4:junit4] 2> 411 T500 oasc.CoreContainer.<init> New CoreContainer 29664087
[junit4:junit4] 2> 412 T500 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713\'
[junit4:junit4] 2> 412 T500 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713\'
[junit4:junit4] 2> 440 T500 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 440 T500 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 441 T500 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 441 T500 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 441 T500 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 441 T500 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 441 T500 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 441 T500 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 442 T500 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 442 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 458 T500 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 473 T500 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:53430/solr
[junit4:junit4] 2> 473 T500 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 473 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@c169b0
[junit4:junit4] 2> 474 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 476 T519 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 476 T519 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 476 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53442
[junit4:junit4] 2> 476 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53442
[junit4:junit4] 2> 488 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0002 with negotiated timeout 20000 for client /127.0.0.1:53442
[junit4:junit4] 2> 488 T519 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0002, negotiated timeout = 20000
[junit4:junit4] 2> 488 T520 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c169b0 name:ZooKeeperConnection Watcher:127.0.0.1:53430 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 489 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 491 T505 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d39a7652f0002
[junit4:junit4] 2> 493 T500 oaz.ZooKeeper.close Session: 0x13d39a7652f0002 closed
[junit4:junit4] 2> 493 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 493 T502 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:53442 which had sessionid 0x13d39a7652f0002
[junit4:junit4] 2> 494 T520 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 500 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@ce8273
[junit4:junit4] 2> 502 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 503 T521 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 504 T521 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 505 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53445
[junit4:junit4] 2> 505 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53445
[junit4:junit4] 2> 509 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0003 with negotiated timeout 20000 for client /127.0.0.1:53445
[junit4:junit4] 2> 509 T521 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0003, negotiated timeout = 20000
[junit4:junit4] 2> 509 T522 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ce8273 name:ZooKeeperConnection Watcher:127.0.0.1:53430/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 510 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 515 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 518 T500 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 524 T500 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53437_k%2Fi
[junit4:junit4] 2> 525 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:53437_k%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:53437_k%2Fi
[junit4:junit4] 2> 527 T500 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53437_k%2Fi
[junit4:junit4] 2> 533 T500 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 541 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 541 T500 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 544 T500 oasc.Overseer.start Overseer (id=89290958737178627-127.0.0.1:53437_k%2Fi-n_0000000000) starting
[junit4:junit4] 2> 545 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 546 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 547 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 549 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 551 T524 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 552 T500 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 555 T500 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 557 T523 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 561 T525 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713\collection1
[junit4:junit4] 2> 561 T525 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 561 T525 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 561 T525 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 562 T525 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713\collection1\'
[junit4:junit4] 2> 563 T525 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 564 T525 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713/collection1/lib/README' to classloader
[junit4:junit4] 2> 604 T525 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 652 T525 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 654 T525 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 657 T525 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1167 T525 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1176 T525 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1179 T525 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1190 T525 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1194 T525 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1197 T525 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1199 T525 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1199 T525 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1199 T525 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1200 T525 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1200 T525 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1200 T525 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-controljetty-1362471904713\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/control/data\
[junit4:junit4] 2> 1201 T525 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e184cb
[junit4:junit4] 2> 1201 T525 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1202 T525 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data forceNew:false
[junit4:junit4] 2> 1202 T525 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data
[junit4:junit4] 2> 1202 T525 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/control/data\index/
[junit4:junit4] 2> 1203 T525 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1204 T525 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data\index forceNew:false
[junit4:junit4] 2> 1207 T525 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@171a7e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec1cad)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1207 T525 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1209 T525 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data\index
[junit4:junit4] 2> 1210 T525 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1210 T525 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1211 T525 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1212 T525 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1212 T525 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1212 T525 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1212 T525 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1213 T525 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1213 T525 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1221 T525 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1228 T525 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data
[junit4:junit4] 2> 1229 T525 oass.SolrIndexSearcher.<init> Opening Searcher@1ecf8c1 main
[junit4:junit4] 2> 1229 T525 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data\tlog
[junit4:junit4] 2> 1230 T525 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1230 T525 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1235 T525 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data
[junit4:junit4] 2> 1235 T526 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ecf8c1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1236 T525 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1236 T525 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1237 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 1519 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1520 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:53437_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53437/k/i"}
[junit4:junit4] 2> 1520 T523 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1520 T523 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 1520 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 1527 T522 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> 1881 T525 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1881 T525 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53437/k/i collection:control_collection shard:shard1
[junit4:junit4] 2> 1883 T525 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1900 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 1902 T525 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1903 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 1908 T525 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1908 T525 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1910 T525 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53437/k/i/collection1/
[junit4:junit4] 2> 1910 T525 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1910 T525 oasc.SyncStrategy.syncToMe http://127.0.0.1:53437/k/i/collection1/ has no replicas
[junit4:junit4] 2> 1910 T525 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53437/k/i/collection1/
[junit4:junit4] 2> 1910 T525 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1922 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2493 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2515 T522 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> 2544 T525 oasc.ZkController.register We are http://127.0.0.1:53437/k/i/collection1/ and leader is http://127.0.0.1:53437/k/i/collection1/
[junit4:junit4] 2> 2544 T525 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53437/k/i
[junit4:junit4] 2> 2544 T525 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2544 T525 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2545 T525 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2550 T525 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2551 T500 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2551 T500 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2552 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2563 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2564 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@29bf49
[junit4:junit4] 2> 2565 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2566 T528 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 2566 T528 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 2566 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53448
[junit4:junit4] 2> 2566 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53448
[junit4:junit4] 2> 2569 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0004 with negotiated timeout 10000 for client /127.0.0.1:53448
[junit4:junit4] 2> 2569 T528 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0004, negotiated timeout = 10000
[junit4:junit4] 2> 2569 T529 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@29bf49 name:ZooKeeperConnection Watcher:127.0.0.1:53430/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2570 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2571 T500 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2572 T500 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 2827 T500 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 2829 T500 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53449
[junit4:junit4] 2> 2829 T500 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2829 T500 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2830 T500 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124
[junit4:junit4] 2> 2830 T500 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124\solr.xml
[junit4:junit4] 2> 2830 T500 oasc.CoreContainer.<init> New CoreContainer 3240747
[junit4:junit4] 2> 2831 T500 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124\'
[junit4:junit4] 2> 2831 T500 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124\'
[junit4:junit4] 2> 2863 T500 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2863 T500 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2864 T500 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2864 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2874 T500 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 2900 T500 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:53430/solr
[junit4:junit4] 2> 2901 T500 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2901 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@c8daa0
[junit4:junit4] 2> 2902 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2903 T539 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 2904 T539 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 2904 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53454
[junit4:junit4] 2> 2904 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53454
[junit4:junit4] 2> 2914 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0005 with negotiated timeout 20000 for client /127.0.0.1:53454
[junit4:junit4] 2> 2914 T539 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0005, negotiated timeout = 20000
[junit4:junit4] 2> 2914 T540 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c8daa0 name:ZooKeeperConnection Watcher:127.0.0.1:53430 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2915 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2916 T505 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d39a7652f0005
[junit4:junit4] 2> 2917 T500 oaz.ZooKeeper.close Session: 0x13d39a7652f0005 closed
[junit4:junit4] 2> 2917 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2917 T540 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 2917 T502 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:53454 which had sessionid 0x13d39a7652f0005
[junit4:junit4] 2> 2926 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d8e34f
[junit4:junit4] 2> 2929 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2929 T541 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 2930 T541 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 2930 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53457
[junit4:junit4] 2> 2931 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53457
[junit4:junit4] 2> 2932 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0006 with negotiated timeout 20000 for client /127.0.0.1:53457
[junit4:junit4] 2> 2932 T541 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0006, negotiated timeout = 20000
[junit4:junit4] 2> 2932 T542 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d8e34f name:ZooKeeperConnection Watcher:127.0.0.1:53430/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2933 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2934 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2935 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2937 T500 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3489 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3490 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:53437_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53437/k/i"}
[junit4:junit4] 2> 3504 T529 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> 3504 T542 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> 3507 T522 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> 3578 T500 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53449_k%2Fi
[junit4:junit4] 2> 3579 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0006 type:delete cxid:0xb zxid:0x4f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:53449_k%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:53449_k%2Fi
[junit4:junit4] 2> 3582 T500 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53449_k%2Fi
[junit4:junit4] 2> 3586 T529 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> 3587 T542 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> 3587 T522 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> 3591 T529 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 3592 T522 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 3593 T542 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 3598 T543 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124\collection1
[junit4:junit4] 2> 3598 T543 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 3599 T543 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 3599 T543 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 3600 T543 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124\collection1\'
[junit4:junit4] 2> 3601 T543 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 3602 T543 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124/collection1/lib/README' to classloader
[junit4:junit4] 2> 3643 T543 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 3698 T543 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 3699 T543 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 3702 T543 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 4204 T543 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 4211 T543 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 4215 T543 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 4228 T543 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4231 T543 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4235 T543 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4237 T543 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 4237 T543 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 4238 T543 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4238 T543 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 4239 T543 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 4239 T543 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty1-1362471907124\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/jetty1\
[junit4:junit4] 2> 4239 T543 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e184cb
[junit4:junit4] 2> 4239 T543 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 4240 T543 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1 forceNew:false
[junit4:junit4] 2> 4240 T543 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1
[junit4:junit4] 2> 4240 T543 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/jetty1\index/
[junit4:junit4] 2> 4240 T543 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 4241 T543 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1\index forceNew:false
[junit4:junit4] 2> 4243 T543 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1615685 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1db9b4f)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 4243 T543 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 4244 T543 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1\index
[junit4:junit4] 2> 4246 T543 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 4246 T543 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 4246 T543 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 4246 T543 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 4247 T543 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 4247 T543 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 4247 T543 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 4248 T543 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 4248 T543 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 4254 T543 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 4259 T543 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1
[junit4:junit4] 2> 4259 T543 oass.SolrIndexSearcher.<init> Opening Searcher@d10a3c main
[junit4:junit4] 2> 4259 T543 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1\tlog
[junit4:junit4] 2> 4260 T543 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 4260 T543 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 4265 T544 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d10a3c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 4266 T543 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 4266 T543 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 4475 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 4476 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:53449_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53449/k/i"}
[junit4:junit4] 2> 4476 T523 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 4477 T523 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 4491 T529 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> 4491 T522 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> 4496 T542 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> 4909 T543 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 4909 T543 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53449/k/i collection:collection1 shard:shard1
[junit4:junit4] 2> 4911 T543 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 4937 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0006 type:delete cxid:0x48 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 4940 T543 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 4941 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0006 type:create cxid:0x49 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4947 T543 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 4947 T543 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 4948 T543 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53449/k/i/collection1/
[junit4:junit4] 2> 4948 T543 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 4948 T543 oasc.SyncStrategy.syncToMe http://127.0.0.1:53449/k/i/collection1/ has no replicas
[junit4:junit4] 2> 4949 T543 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53449/k/i/collection1/
[junit4:junit4] 2> 4949 T543 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 4959 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0006 type:create cxid:0x53 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 5464 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5473 T522 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> 5473 T529 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> 5474 T542 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> 5484 T543 oasc.ZkController.register We are http://127.0.0.1:53449/k/i/collection1/ and leader is http://127.0.0.1:53449/k/i/collection1/
[junit4:junit4] 2> 5484 T543 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53449/k/i
[junit4:junit4] 2> 5484 T543 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 5484 T543 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 5484 T543 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 5488 T543 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5488 T500 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 5489 T500 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 5489 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 5744 T500 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 5745 T500 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53458
[junit4:junit4] 2> 5745 T500 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 5746 T500 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 5746 T500 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048
[junit4:junit4] 2> 5746 T500 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048\solr.xml
[junit4:junit4] 2> 5747 T500 oasc.CoreContainer.<init> New CoreContainer 27401341
[junit4:junit4] 2> 5747 T500 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048\'
[junit4:junit4] 2> 5747 T500 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048\'
[junit4:junit4] 2> 5775 T500 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 5775 T500 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 5775 T500 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 5775 T500 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 5776 T500 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 5776 T500 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 5777 T500 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 5777 T500 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 5777 T500 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 5777 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 5786 T500 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 5804 T500 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:53430/solr
[junit4:junit4] 2> 5804 T500 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 5805 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@19d98ba
[junit4:junit4] 2> 5805 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 5806 T555 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 5807 T555 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 5807 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53463
[junit4:junit4] 2> 5807 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53463
[junit4:junit4] 2> 5818 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0007 with negotiated timeout 20000 for client /127.0.0.1:53463
[junit4:junit4] 2> 5818 T555 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0007, negotiated timeout = 20000
[junit4:junit4] 2> 5818 T556 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19d98ba name:ZooKeeperConnection Watcher:127.0.0.1:53430 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 5818 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 5820 T505 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d39a7652f0007
[junit4:junit4] 2> 5822 T500 oaz.ZooKeeper.close Session: 0x13d39a7652f0007 closed
[junit4:junit4] 2> 5822 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 5822 T502 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:53463 which had sessionid 0x13d39a7652f0007
[junit4:junit4] 2> 5822 T556 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 5828 T500 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:53430/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@89e731
[junit4:junit4] 2> 5829 T500 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 5830 T557 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:53430. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 5830 T557 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:53430, initiating session
[junit4:junit4] 2> 5830 T502 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:53466
[junit4:junit4] 2> 5830 T502 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:53466
[junit4:junit4] 2> 5832 T504 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d39a7652f0008 with negotiated timeout 20000 for client /127.0.0.1:53466
[junit4:junit4] 2> 5832 T557 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:53430, sessionid = 0x13d39a7652f0008, negotiated timeout = 20000
[junit4:junit4] 2> 5832 T558 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@89e731 name:ZooKeeperConnection Watcher:127.0.0.1:53430/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 5832 T500 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 5833 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 5834 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 5836 T500 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 6443 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6444 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:53449_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53449/k/i"}
[junit4:junit4] 2> 6458 T542 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> 6458 T529 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> 6458 T558 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> 6460 T522 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> 6480 T500 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53458_k%2Fi
[junit4:junit4] 2> 6481 T505 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d39a7652f0008 type:delete cxid:0xb zxid:0x73 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:53458_k%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:53458_k%2Fi
[junit4:junit4] 2> 6483 T500 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53458_k%2Fi
[junit4:junit4] 2> 6489 T542 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> 6490 T522 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> 6489 T529 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> 6491 T558 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 6491 T558 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> 6498 T542 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 6498 T522 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 6499 T529 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 6505 T559 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048\collection1
[junit4:junit4] 2> 6505 T559 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 6506 T559 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 6506 T559 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 6507 T559 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048\collection1\'
[junit4:junit4] 2> 6509 T559 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 6509 T559 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048/collection1/lib/README' to classloader
[junit4:junit4] 2> 6549 T559 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 6600 T559 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 6602 T559 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 6605 T559 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 7177 T559 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 7187 T559 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 7190 T559 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 7204 T559 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 7207 T559 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 7210 T559 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 7212 T559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 7212 T559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 7212 T559 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 7213 T559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 7213 T559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 7213 T559 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-jetty2-1362471910048\collection1\, dataDir=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/jetty2\
[junit4:junit4] 2> 7213 T559 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e184cb
[junit4:junit4] 2> 7214 T559 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 7214 T559 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2 forceNew:false
[junit4:junit4] 2> 7214 T559 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 7214 T559 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/jetty2\index/
[junit4:junit4] 2> 7214 T559 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory '.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 7214 T559 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index forceNew:false
[junit4:junit4] 2> 7217 T559 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@bd238b lockFactory=org.apache.lucene.store.NativeFSLockFactory@14ad9fb)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 7218 T559 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 7219 T559 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 7220 T559 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 7220 T559 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 7220 T559 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 7221 T559 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 7221 T559 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 7221 T559 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 7221 T559 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 7222 T559 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 7222 T559 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 7228 T559 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 7232 T559 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 7232 T559 oass.SolrIndexSearcher.<init> Opening Searcher@124e0f2 main
[junit4:junit4] 2> 7232 T559 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\tlog
[junit4:junit4] 2> 7234 T559 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 7234 T559 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 7237 T560 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@124e0f2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 7238 T559 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 7238 T559 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 7527 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7528 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:53458_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53458/k/i"}
[junit4:junit4] 2> 7528 T523 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 7529 T523 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 7541 T542 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> 7541 T558 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> 7541 T522 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> 7541 T529 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> 7945 T559 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7945 T559 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53458/k/i collection:collection1 shard:shard1
[junit4:junit4] 2> 7953 T559 oasc.ZkController.register We are http://127.0.0.1:53458/k/i/collection1/ and leader is http://127.0.0.1:53449/k/i/collection1/
[junit4:junit4] 2> 7953 T559 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53458/k/i
[junit4:junit4] 2> 7953 T559 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 7953 T559 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C62 name=collection1 org.apache.solr.core.SolrCore@825b44 url=http://127.0.0.1:53458/k/i/collection1 node=127.0.0.1:53458_k%2Fi C62_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53458_k%2Fi, base_url=http://127.0.0.1:53458/k/i}
[junit4:junit4] 2> 7953 T561 C62 P53458 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 7955 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 7956 T559 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7956 T561 C62 P53458 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 7956 T561 C62 P53458 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 7957 T500 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 7957 T500 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 7957 T500 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 7959 T561 C62 P53458 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 7968 T500 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C63 name=collection1 org.apache.solr.core.SolrCore@122b3ca url=http://127.0.0.1:53437/k/i/collection1 node=127.0.0.1:53437_k%2Fi C63_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:53437_k%2Fi, base_url=http://127.0.0.1:53437/k/i, leader=true}
[junit4:junit4] 2> 7985 T516 C63 P53437 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\control\data
[junit4:junit4] 2> 7988 T516 C63 P53437 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@171a7e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec1cad)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 7988 T516 C63 P53437 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 7992 T515 C63 P53437 /update {wt=javabin&version=2} {add=[1 (1428655348160397312)]} 0 8
[junit4:junit4] 2> 7992 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10001 (1428655348160397313)]} 0 8
[junit4:junit4] 2> ASYNC NEW_CORE C64 name=collection1 org.apache.solr.core.SolrCore@7fafa4 url=http://127.0.0.1:53449/k/i/collection1 node=127.0.0.1:53449_k%2Fi C64_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53449_k%2Fi, base_url=http://127.0.0.1:53449/k/i, leader=true}
[junit4:junit4] 2> 8012 T533 C64 P53449 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1
[junit4:junit4] 2> 8014 T533 C64 P53449 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1615685 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1db9b4f)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 8015 T533 C64 P53449 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 8018 T538 C64 P53449 /update {wt=javabin&version=2} {add=[1 (1428655348187660289)]} 0 7
[junit4:junit4] 2> 8018 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10001 (1428655348187660288)]} 0 7
[junit4:junit4] 2> 8052 T517 C63 P53437 /update {wt=javabin&version=2} {add=[2 (1428655348230651904)]} 0 1
[junit4:junit4] 2> 8052 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10002 (1428655348230651905)]} 0 0
[junit4:junit4] 2> 8057 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10002 (1428655348235894785)]} 0 1
[junit4:junit4] 2> 8058 T535 C64 P53449 /update {wt=javabin&version=2} {add=[2 (1428655348235894784)]} 0 2
[junit4:junit4] 2> 8093 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[1 (-1428655348271546368)]} 0 2
[junit4:junit4] 2> 8093 T513 C63 P53437 /update {wt=javabin&version=2} {delete=[10001 (-1428655348271546369)]} 0 2
[junit4:junit4] 2> 8096 T538 C64 P53449 /update {wt=javabin&version=2} {delete=[10001 (-1428655348275740672)]} 0 1
[junit4:junit4] 2> 8096 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[1 (-1428655348275740673)]} 0 1
[junit4:junit4] 2> 8099 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10003 (1428655348278886401)]} 0 1
[junit4:junit4] 2> 8100 T517 C63 P53437 /update {wt=javabin&version=2} {add=[3 (1428655348278886400)]} 0 2
[junit4:junit4] 2> 8102 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10003 (1428655348282032128)]} 0 1
[junit4:junit4] 2> 8102 T534 C64 P53449 /update {wt=javabin&version=2} {add=[3 (1428655348283080704)]} 0 0
[junit4:junit4] 2> 8172 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10004 (1428655348356481024)]} 0 0
[junit4:junit4] 2> 8173 T514 C63 P53437 /update {wt=javabin&version=2} {add=[4 (1428655348356481025)]} 0 1
[junit4:junit4] 2> 8176 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10004 (1428655348359626753)]} 0 1
[junit4:junit4] 2> 8176 T535 C64 P53449 /update {wt=javabin&version=2} {add=[4 (1428655348359626752)]} 0 1
[junit4:junit4] 2> 8229 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10005 (1428655348416249856)]} 0 1
[junit4:junit4] 2> 8229 T515 C63 P53437 /update {wt=javabin&version=2} {add=[5 (1428655348416249857)]} 0 0
[junit4:junit4] 2> 8232 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10005 (1428655348418347008)]} 0 1
[junit4:junit4] 2> 8232 T533 C64 P53449 /update {wt=javabin&version=2} {add=[5 (1428655348419395584)]} 0 0
[junit4:junit4] 2> 8258 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10006 (1428655348445609984)]} 0 1
[junit4:junit4] 2> 8258 T517 C63 P53437 /update {wt=javabin&version=2} {add=[6 (1428655348445609985)]} 0 1
[junit4:junit4] 2> 8260 T538 C64 P53449 /update {wt=javabin&version=2} {add=[6 (1428655348448755712)]} 0 0
[junit4:junit4] 2> 8260 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10006 (1428655348448755713)]} 0 0
[junit4:junit4] 2> 8271 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[10004 (-1428655348460290048)]} 0 0
[junit4:junit4] 2> 8271 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[4 (-1428655348460290049)]} 0 0
[junit4:junit4] 2> 8273 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[10004 (-1428655348462387200)]} 0 0
[junit4:junit4] 2> 8273 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[4 (-1428655348462387201)]} 0 0
[junit4:junit4] 2> 8276 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10007 (1428655348464484352)]} 0 1
[junit4:junit4] 2> 8276 T515 C63 P53437 /update {wt=javabin&version=2} {add=[7 (1428655348464484353)]} 0 1
[junit4:junit4] 2> 8279 T533 C64 P53449 /update {wt=javabin&version=2} {add=[7 (1428655348467630080)]} 0 1
[junit4:junit4] 2> 8279 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10007 (1428655348467630081)]} 0 1
[junit4:junit4] 2> 8323 T517 C63 P53437 /update {wt=javabin&version=2} {add=[8 (1428655348514816000)]} 0 0
[junit4:junit4] 2> 8323 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10008 (1428655348514816001)]} 0 0
[junit4:junit4] 2> 8325 T534 C64 P53449 /update {wt=javabin&version=2} {add=[8 (1428655348516913152)]} 0 0
[junit4:junit4] 2> 8327 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10008 (1428655348519010304)]} 0 0
[junit4:junit4] 2> 8353 T518 C63 P53437 /update {wt=javabin&version=2} {add=[9 (1428655348545224704)]} 0 1
[junit4:junit4] 2> 8354 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10009 (1428655348546273280)]} 0 1
[junit4:junit4] 2> 8356 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10009 (1428655348548370433)]} 0 1
[junit4:junit4] 2> 8356 T533 C64 P53449 /update {wt=javabin&version=2} {add=[9 (1428655348548370432)]} 0 1
[junit4:junit4] 2> 8396 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10010 (1428655348591362048)]} 0 0
[junit4:junit4] 2> 8396 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10 (1428655348591362049)]} 0 0
[junit4:junit4] 2> 8399 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10 (1428655348593459200)]} 0 0
[junit4:junit4] 2> 8400 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10010 (1428655348594507776)]} 0 1
[junit4:junit4] 2> 8453 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[5 (-1428655348651130880)]} 0 1
[junit4:junit4] 2> 8454 T517 C63 P53437 /update {wt=javabin&version=2} {delete=[10005 (-1428655348652179456)]} 0 0
[junit4:junit4] 2> 8455 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[5 (-1428655348653228032)]} 0 0
[junit4:junit4] 2> 8456 T533 C64 P53449 /update {wt=javabin&version=2} {delete=[10005 (-1428655348654276608)]} 0 0
[junit4:junit4] 2> 8457 T518 C63 P53437 /update {wt=javabin&version=2} {add=[11 (1428655348655325184)]} 0 0
[junit4:junit4] 2> 8461 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10011 (1428655348659519488)]} 0 1
[junit4:junit4] 2> 8461 T534 C64 P53449 /update {wt=javabin&version=2} {add=[11 (1428655348659519488)]} 0 1
[junit4:junit4] 2> 8463 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10011 (1428655348661616640)]} 0 0
[junit4:junit4] 2> 8464 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[6 (-1428655348662665216)]} 0 0
[junit4:junit4] 2> 8466 T513 C63 P53437 /update {wt=javabin&version=2} {delete=[10006 (-1428655348664762368)]} 0 0
[junit4:junit4] 2> 8468 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[6 (-1428655348666859520)]} 0 0
[junit4:junit4] 2> 8469 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10006 (-1428655348667908096)]} 0 0
[junit4:junit4] 2> 8470 T516 C63 P53437 /update {wt=javabin&version=2} {add=[12 (1428655348668956672)]} 0 0
[junit4:junit4] 2> 8472 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10012 (1428655348670005248)]} 0 1
[junit4:junit4] 2> 8473 T533 C64 P53449 /update {wt=javabin&version=2} {add=[12 (1428655348671053824)]} 0 1
[junit4:junit4] 2> 8474 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10012 (1428655348673150976)]} 0 0
[junit4:junit4] 2> 8486 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[10 (-1428655348685733888)]} 0 0
[junit4:junit4] 2> 8487 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[10010 (-1428655348686782464)]} 0 0
[junit4:junit4] 2> 8488 T538 C64 P53449 /update {wt=javabin&version=2} {delete=[10010 (-1428655348687831040)]} 0 0
[junit4:junit4] 2> 8488 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[10 (-1428655348687831041)]} 0 0
[junit4:junit4] 2> 8491 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10013 (1428655348689928192)]} 0 1
[junit4:junit4] 2> 8491 T513 C63 P53437 /update {wt=javabin&version=2} {add=[13 (1428655348689928193)]} 0 1
[junit4:junit4] 2> 8494 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10013 (1428655348693073920)]} 0 1
[junit4:junit4] 2> 8494 T533 C64 P53449 /update {wt=javabin&version=2} {add=[13 (1428655348693073921)]} 0 1
[junit4:junit4] 2> 8533 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10014 (1428655348733968384)]} 0 1
[junit4:junit4] 2> 8533 T518 C63 P53437 /update {wt=javabin&version=2} {add=[14 (1428655348733968385)]} 0 1
[junit4:junit4] 2> 8536 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10014 (1428655348737114112)]} 0 1
[junit4:junit4] 2> 8536 T534 C64 P53449 /update {wt=javabin&version=2} {add=[14 (1428655348737114113)]} 0 1
[junit4:junit4] 2> 8601 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[10013 (-1428655348805271552)]} 0 1
[junit4:junit4] 2> 8601 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[13 (-1428655348806320128)]} 0 0
[junit4:junit4] 2> 8603 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10013 (-1428655348808417280)]} 0 0
[junit4:junit4] 2> 8603 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[13 (-1428655348808417281)]} 0 0
[junit4:junit4] 2> 8606 T513 C63 P53437 /update {wt=javabin&version=2} {add=[15 (1428655348810514432)]} 0 1
[junit4:junit4] 2> 8606 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10015 (1428655348810514433)]} 0 1
[junit4:junit4] 2> 8606 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8607 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:53458_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53458/k/i"}
[junit4:junit4] 2> 8608 T533 C64 P53449 /update {wt=javabin&version=2} {add=[15 (1428655348813660160)]} 0 0
[junit4:junit4] 2> 8610 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10015 (1428655348815757312)]} 0 1
[junit4:junit4] 2> 8616 T529 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> 8616 T542 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> 8621 T558 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> 8620 T522 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> 8660 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[14 (-1428655348868186112)]} 0 1
[junit4:junit4] 2> 8661 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[10014 (-1428655348869234688)]} 0 0
[junit4:junit4] 2> C62_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53458_k%2Fi, base_url=http://127.0.0.1:53458/k/i}
[junit4:junit4] 2> 8674 T549 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 8676 T549 C62 P53458 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@bd238b lockFactory=org.apache.lucene.store.NativeFSLockFactory@14ad9fb)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 8677 T549 C62 P53458 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 8679 T554 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[14 (-1428655348871331840)]} 0 7
[junit4:junit4] 2> 8679 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10014 (-1428655348873428992)]} 0 7
[junit4:junit4] 2> 8680 T534 C64 P53449 /update {wt=javabin&version=2} {delete=[14 (-1428655348871331840)]} 0 17
[junit4:junit4] 2> 8680 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10014 (-1428655348873428992)]} 0 17
[junit4:junit4] 2> 8683 T515 C63 P53437 /update {wt=javabin&version=2} {add=[16 (1428655348891254784)]} 0 1
[junit4:junit4] 2> 8683 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10016 (1428655348891254785)]} 0 1
[junit4:junit4] 2> 8688 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1428655348893351936)]} 0 1
[junit4:junit4] 2> 8689 T533 C64 P53449 /update {wt=javabin&version=2} {add=[16 (1428655348893351936)]} 0 5
[junit4:junit4] 2> 8689 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10016 (1428655348894400512)]} 0 1
[junit4:junit4] 2> 8689 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10016 (1428655348894400512)]} 0 4
[junit4:junit4] 2> 8751 T513 C63 P53437 /update {wt=javabin&version=2} {add=[17 (1428655348963606528)]} 0 0
[junit4:junit4] 2> 8753 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10017 (1428655348965703680)]} 0 0
[junit4:junit4] 2> 8757 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1428655348967800832)]} 0 1
[junit4:junit4] 2> 8757 T536 C64 P53449 /update {wt=javabin&version=2} {add=[17 (1428655348967800832)]} 0 3
[junit4:junit4] 2> 8759 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10017 (1428655348967800833)]} 0 1
[junit4:junit4] 2> 8760 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10017 (1428655348967800833)]} 0 5
[junit4:junit4] 2> 8763 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[16 (-1428655348976189440)]} 0 0
[junit4:junit4] 2> 8764 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[10016 (-1428655348977238016)]} 0 0
[junit4:junit4] 2> 8766 T554 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[16 (-1428655348978286592)]} 0 0
[junit4:junit4] 2> 8767 T534 C64 P53449 /update {wt=javabin&version=2} {delete=[16 (-1428655348978286592)]} 0 2
[junit4:junit4] 2> 8768 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10016 (-1428655348979335168)]} 0 0
[junit4:junit4] 2> 8768 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10016 (-1428655348979335168)]} 0 2
[junit4:junit4] 2> 8770 T515 C63 P53437 /update {wt=javabin&version=2} {add=[18 (1428655348982480896)]} 0 1
[junit4:junit4] 2> 8771 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10018 (1428655348984578048)]} 0 0
[junit4:junit4] 2> 8774 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1428655348984578048)]} 0 0
[junit4:junit4] 2> 8775 T533 C64 P53449 /update {wt=javabin&version=2} {add=[18 (1428655348984578048)]} 0 4
[junit4:junit4] 2> 8775 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1428655348986675200)]} 0 0
[junit4:junit4] 2> 8776 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10018 (1428655348986675200)]} 0 3
[junit4:junit4] 2> 8845 T513 C63 P53437 /update {wt=javabin&version=2} {delete=[17 (-1428655349062172672)]} 0 0
[junit4:junit4] 2> 8847 T517 C63 P53437 /update {wt=javabin&version=2} {delete=[10017 (-1428655349064269824)]} 0 0
[junit4:junit4] 2> 8849 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[17 (-1428655349065318400)]} 0 0
[junit4:junit4] 2> 8850 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10017 (-1428655349066366976)]} 0 0
[junit4:junit4] 2> 8850 T536 C64 P53449 /update {wt=javabin&version=2} {delete=[17 (-1428655349065318400)]} 0 3
[junit4:junit4] 2> 8851 T534 C64 P53449 /update {wt=javabin&version=2} {delete=[10017 (-1428655349066366976)]} 0 2
[junit4:junit4] 2> 8853 T518 C63 P53437 /update {wt=javabin&version=2} {add=[19 (1428655349069512704)]} 0 1
[junit4:junit4] 2> 8854 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10019 (1428655349070561280)]} 0 1
[junit4:junit4] 2> 8858 T554 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1428655349072658432)]} 0 1
[junit4:junit4] 2> 8858 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1428655349073707008)]} 0 0
[junit4:junit4] 2> 8859 T537 C64 P53449 /update {wt=javabin&version=2} {add=[19 (1428655349072658432)]} 0 4
[junit4:junit4] 2> 8859 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10019 (1428655349073707008)]} 0 3
[junit4:junit4] 2> 8862 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10020 (1428655349078949889)]} 0 1
[junit4:junit4] 2> 8863 T515 C63 P53437 /update {wt=javabin&version=2} {add=[20 (1428655349078949888)]} 0 2
[junit4:junit4] 2> 8867 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1428655349083144193)]} 0 0
[junit4:junit4] 2> 8867 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1428655349083144192)]} 0 0
[junit4:junit4] 2> 8869 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10020 (1428655349083144193)]} 0 4
[junit4:junit4] 2> 8869 T535 C64 P53449 /update {wt=javabin&version=2} {add=[20 (1428655349083144192)]} 0 4
[junit4:junit4] 2> 8940 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10021 (1428655349160738816)]} 0 1
[junit4:junit4] 2> 8940 T516 C63 P53437 /update {wt=javabin&version=2} {add=[21 (1428655349161787392)]} 0 0
[junit4:junit4] 2> 8945 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1428655349163884545)]} 0 1
[junit4:junit4] 2> 8945 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1428655349163884544)]} 0 1
[junit4:junit4] 2> 8946 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10021 (1428655349163884545)]} 0 4
[junit4:junit4] 2> 8946 T536 C64 P53449 /update {wt=javabin&version=2} {add=[21 (1428655349163884544)]} 0 4
[junit4:junit4] 2> 8962 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[10018 (-1428655349184856064)]} 0 1
[junit4:junit4] 2> 8963 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[18 (-1428655349185904640)]} 0 0
[junit4:junit4] 2> 8966 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10018 (-1428655349185904640)]} 0 0
[junit4:junit4] 2> 8966 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10018 (-1428655349185904640)]} 0 3
[junit4:junit4] 2> 8967 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[18 (-1428655349189050368)]} 0 0
[junit4:junit4] 2> 8968 T533 C64 P53449 /update {wt=javabin&version=2} {delete=[18 (-1428655349189050368)]} 0 2
[junit4:junit4] 2> 8969 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10022 (1428655349191147520)]} 0 1
[junit4:junit4] 2> 8970 T517 C63 P53437 /update {wt=javabin&version=2} {add=[22 (1428655349193244672)]} 0 0
[junit4:junit4] 2> 8974 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1428655349194293248)]} 0 1
[junit4:junit4] 2> 8974 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10022 (1428655349194293248)]} 0 3
[junit4:junit4] 2> 8976 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1428655349195341824)]} 0 1
[junit4:junit4] 2> 8976 T535 C64 P53449 /update {wt=javabin&version=2} {add=[22 (1428655349195341824)]} 0 4
[junit4:junit4] 2> 9042 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10023 (1428655349267693568)]} 0 1
[junit4:junit4] 2> 9043 T516 C63 P53437 /update {wt=javabin&version=2} {add=[23 (1428655349269790720)]} 0 1
[junit4:junit4] 2> 9047 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1428655349271887872)]} 0 0
[junit4:junit4] 2> 9048 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10023 (1428655349271887872)]} 0 3
[junit4:junit4] 2> 9049 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1428655349271887873)]} 0 1
[junit4:junit4] 2> 9049 T536 C64 P53449 /update {wt=javabin&version=2} {add=[23 (1428655349271887873)]} 0 4
[junit4:junit4] 2> 9088 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[10019 (-1428655349316976640)]} 0 0
[junit4:junit4] 2> 9088 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[19 (-1428655349316976641)]} 0 0
[junit4:junit4] 2> 9091 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10019 (-1428655349319073792)]} 0 0
[junit4:junit4] 2> 9092 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[19 (-1428655349320122368)]} 0 0
[junit4:junit4] 2> 9093 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10019 (-1428655349319073792)]} 0 3
[junit4:junit4] 2> 9093 T533 C64 P53449 /update {wt=javabin&version=2} {delete=[19 (-1428655349320122368)]} 0 2
[junit4:junit4] 2> 9095 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10024 (1428655349324316672)]} 0 0
[junit4:junit4] 2> 9096 T517 C63 P53437 /update {wt=javabin&version=2} {add=[24 (1428655349324316673)]} 0 1
[junit4:junit4] 2> 9099 T554 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1428655349326413824)]} 0 0
[junit4:junit4] 2> 9100 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10024 (1428655349326413824)]} 0 3
[junit4:junit4] 2> 9102 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1428655349328510976)]} 0 1
[junit4:junit4] 2> 9102 T535 C64 P53449 /update {wt=javabin&version=2} {add=[24 (1428655349328510976)]} 0 3
[junit4:junit4] 2> 9139 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10025 (1428655349370454016)]} 0 1
[junit4:junit4] 2> 9139 T516 C63 P53437 /update {wt=javabin&version=2} {add=[25 (1428655349370454017)]} 0 0
[junit4:junit4] 2> 9143 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1428655349372551168)]} 0 0
[junit4:junit4] 2> 9143 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10025 (1428655349372551168)]} 0 2
[junit4:junit4] 2> 9145 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1428655349373599744)]} 0 1
[junit4:junit4] 2> 9145 T536 C64 P53449 /update {wt=javabin&version=2} {add=[25 (1428655349373599744)]} 0 3
[junit4:junit4] 2> 9192 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[10021 (-1428655349426028544)]} 0 0
[junit4:junit4] 2> 9194 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[21 (-1428655349428125696)]} 0 0
[junit4:junit4] 2> 9197 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[21 (-1428655349430222848)]} 0 0
[junit4:junit4] 2> 9198 T533 C64 P53449 /update {wt=javabin&version=2} {delete=[21 (-1428655349430222848)]} 0 2
[junit4:junit4] 2> 9198 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10021 (-1428655349429174272)]} 0 0
[junit4:junit4] 2> 9198 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[10021 (-1428655349429174272)]} 0 3
[junit4:junit4] 2> 9200 T514 C63 P53437 /update {wt=javabin&version=2} {add=[26 (1428655349434417152)]} 0 0
[junit4:junit4] 2> 9202 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10026 (1428655349435465728)]} 0 1
[junit4:junit4] 2> 9205 T554 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1428655349436514304)]} 0 0
[junit4:junit4] 2> 9206 T538 C64 P53449 /update {wt=javabin&version=2} {add=[26 (1428655349436514304)]} 0 4
[junit4:junit4] 2> 9207 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1428655349437562880)]} 0 1
[junit4:junit4] 2> 9207 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10026 (1428655349437562880)]} 0 4
[junit4:junit4] 2> 9254 T513 C63 P53437 /update {wt=javabin&version=2} {delete=[26 (-1428655349491040256)]} 0 0
[junit4:junit4] 2> 9255 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[10026 (-1428655349492088832)]} 0 0
[junit4:junit4] 2> 9258 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[26 (-1428655349493137408)]} 0 0
[junit4:junit4] 2> 9258 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10026 (-1428655349494185984)]} 0 0
[junit4:junit4] 2> 9259 T534 C64 P53449 /update {wt=javabin&version=2} {delete=[26 (-1428655349493137408)]} 0 3
[junit4:junit4] 2> 9259 T533 C64 P53449 /update {wt=javabin&version=2} {delete=[10026 (-1428655349494185984)]} 0 2
[junit4:junit4] 2> 9262 T515 C63 P53437 /update {wt=javabin&version=2} {add=[27 (1428655349499428864)]} 0 0
[junit4:junit4] 2> 9263 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10027 (1428655349499428865)]} 0 1
[junit4:junit4] 2> 9267 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1428655349502574593)]} 0 0
[junit4:junit4] 2> 9268 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10027 (1428655349502574593)]} 0 3
[junit4:junit4] 2> 9268 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1428655349502574592)]} 0 0
[junit4:junit4] 2> 9269 T537 C64 P53449 /update {wt=javabin&version=2} {add=[27 (1428655349502574592)]} 0 4
[junit4:junit4] 2> 9313 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[10027 (-1428655349552906240)]} 0 0
[junit4:junit4] 2> 9314 T517 C63 P53437 /update {wt=javabin&version=2} {delete=[27 (-1428655349553954816)]} 0 0
[junit4:junit4] 2> 9317 T554 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10027 (-1428655349556051968)]} 0 0
[junit4:junit4] 2> 9318 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[10027 (-1428655349556051968)]} 0 2
[junit4:junit4] 2> 9319 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[27 (-1428655349557100544)]} 0 0
[junit4:junit4] 2> 9319 T536 C64 P53449 /update {wt=javabin&version=2} {delete=[27 (-1428655349557100544)]} 0 2
[junit4:junit4] 2> 9321 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10028 (1428655349560246272)]} 0 1
[junit4:junit4] 2> 9322 T516 C63 P53437 /update {wt=javabin&version=2} {add=[28 (1428655349561294848)]} 0 1
[junit4:junit4] 2> 9325 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1428655349563392000)]} 0 0
[junit4:junit4] 2> 9326 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10028 (1428655349563392000)]} 0 3
[junit4:junit4] 2> 9327 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1428655349564440576)]} 0 1
[junit4:junit4] 2> 9327 T533 C64 P53449 /update {wt=javabin&version=2} {add=[28 (1428655349564440576)]} 0 3
[junit4:junit4] 2> 9378 T500 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 53458
[junit4:junit4] 2> 9378 T500 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=27401341
[junit4:junit4] 2> 9384 T518 C63 P53437 /update {wt=javabin&version=2} {add=[29 (1428655349627355136)]} 0 0
[junit4:junit4] 2> 9385 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10029 (1428655349627355137)]} 0 1
[junit4:junit4] 2> 9511 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1428655349629452288)]} 0 122
[junit4:junit4] 2> 9511 T538 C64 P53449 /update {wt=javabin&version=2} {add=[29 (1428655349629452288)]} 0 125
[junit4:junit4] 2> 9512 T549 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1428655349630500864)]} 0 0
[junit4:junit4] 2> 9513 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10029 (1428655349630500864)]} 0 126
[junit4:junit4] 2> 9582 T517 C63 P53437 /update {wt=javabin&version=2} {add=[30 (1428655349833924608)]} 0 1
[junit4:junit4] 2> 9583 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10030 (1428655349834973184)]} 0 1
[junit4:junit4] 2> 9586 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1428655349837070336)]} 0 0
[junit4:junit4] 2> 9587 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1428655349837070337)]} 0 1
[junit4:junit4] 2> 9587 T535 C64 P53449 /update {wt=javabin&version=2} {add=[30 (1428655349837070336)]} 0 3
[junit4:junit4] 2> 9587 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10030 (1428655349837070337)]} 0 3
[junit4:junit4] 2> 9633 T516 C63 P53437 /update {wt=javabin&version=2} {add=[31 (1428655349887401984)]} 0 1
[junit4:junit4] 2> 9633 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10031 (1428655349887401985)]} 0 1
[junit4:junit4] 2> 9639 T553 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1428655349891596288)]} 0 1
[junit4:junit4] 2> 9639 T551 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1428655349891596289)]} 0 0
[junit4:junit4] 2> 9639 T534 C64 P53449 /update {wt=javabin&version=2} {add=[31 (1428655349891596288)]} 0 3
[junit4:junit4] 2> 9640 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10031 (1428655349891596289)]} 0 4
[junit4:junit4] 2> 9682 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9683 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53458_k%2Fi_collection1",
[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:53458_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53458/k/i"}
[junit4:junit4] 2> 9689 T529 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> 9689 T522 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> 9689 T558 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> 9689 T542 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> 9708 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[10030 (-1428655349967093760)]} 0 0
[junit4:junit4] 2> 9709 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[30 (-1428655349968142336)]} 0 0
[junit4:junit4] 2> 9710 T538 C64 P53449 /update {wt=javabin&version=2} {delete=[10030 (-1428655349969190912)]} 0 0
[junit4:junit4] 2> 9711 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[30 (-1428655349970239488)]} 0 0
[junit4:junit4] 2> 9714 T513 C63 P53437 /update {wt=javabin&version=2} {add=[32 (1428655349972336640)]} 0 1
[junit4:junit4] 2> 9714 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10032 (1428655349973385216)]} 0 1
[junit4:junit4] 2> 9717 T534 C64 P53449 /update {wt=javabin&version=2} {add=[32 (1428655349975482368)]} 0 1
[junit4:junit4] 2> 9717 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10032 (1428655349975482369)]} 0 1
[junit4:junit4] 2> 9728 T514 C63 P53437 /update {wt=javabin&version=2} {add=[33 (1428655349987016705)]} 0 1
[junit4:junit4] 2> 9728 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10033 (1428655349987016704)]} 0 1
[junit4:junit4] 2> 9731 T533 C64 P53449 /update {wt=javabin&version=2} {add=[33 (1428655349990162433)]} 0 1
[junit4:junit4] 2> 9731 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10033 (1428655349990162432)]} 0 1
[junit4:junit4] 2> 9775 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[10031 (-1428655350037348352)]} 0 1
[junit4:junit4] 2> 9775 T518 C63 P53437 /update {wt=javabin&version=2} {delete=[31 (-1428655350037348353)]} 0 1
[junit4:junit4] 2> 9777 T535 C64 P53449 /update {wt=javabin&version=2} {delete=[31 (-1428655350039445504)]} 0 0
[junit4:junit4] 2> 9778 T538 C64 P53449 /update {wt=javabin&version=2} {delete=[10031 (-1428655350040494080)]} 0 0
[junit4:junit4] 2> 9780 T513 C63 P53437 /update {wt=javabin&version=2} {add=[34 (1428655350042591232)]} 0 1
[junit4:junit4] 2> 9781 T517 C63 P53437 /update {wt=javabin&version=2} {add=[10034 (1428655350042591233)]} 0 1
[junit4:junit4] 2> 9783 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10034 (1428655350044688385)]} 0 1
[junit4:junit4] 2> 9783 T534 C64 P53449 /update {wt=javabin&version=2} {add=[34 (1428655350044688384)]} 0 1
[junit4:junit4] 2> 9796 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10035 (1428655350058319872)]} 0 1
[junit4:junit4] 2> 9796 T515 C63 P53437 /update {wt=javabin&version=2} {add=[35 (1428655350058319873)]} 0 1
[junit4:junit4] 2> 9799 T533 C64 P53449 /update {wt=javabin&version=2} {add=[35 (1428655350061465600)]} 0 1
[junit4:junit4] 2> 9799 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10035 (1428655350061465601)]} 0 1
[junit4:junit4] 2> 9811 T517 C63 P53437 /update {wt=javabin&version=2} {add=[36 (1428655350074048513)]} 0 1
[junit4:junit4] 2> 9811 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10036 (1428655350074048512)]} 0 1
[junit4:junit4] 2> 9814 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10036 (1428655350078242816)]} 0 0
[junit4:junit4] 2> 9816 T535 C64 P53449 /update {wt=javabin&version=2} {add=[36 (1428655350080339968)]} 0 0
[junit4:junit4] 2> 9828 T513 C63 P53437 /update {wt=javabin&version=2} {delete=[10036 (-1428655350092922880)]} 0 0
[junit4:junit4] 2> 9829 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[36 (-1428655350093971456)]} 0 0
[junit4:junit4] 2> 9830 T536 C64 P53449 /update {wt=javabin&version=2} {delete=[10036 (-1428655350095020032)]} 0 0
[junit4:junit4] 2> 9833 T534 C64 P53449 /update {wt=javabin&version=2} {delete=[36 (-1428655350098165760)]} 0 0
[junit4:junit4] 2> 9834 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10037 (1428655350098165760)]} 0 1
[junit4:junit4] 2> 9836 T516 C63 P53437 /update {wt=javabin&version=2} {add=[37 (1428655350100262912)]} 0 1
[junit4:junit4] 2> 9836 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10037 (1428655350100262912)]} 0 1
[junit4:junit4] 2> 9838 T537 C64 P53449 /update {wt=javabin&version=2} {add=[37 (1428655350103408640)]} 0 0
[junit4:junit4] 2> 9871 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10038 (1428655350136963072)]} 0 1
[junit4:junit4] 2> 9873 T517 C63 P53437 /update {wt=javabin&version=2} {add=[38 (1428655350140108800)]} 0 0
[junit4:junit4] 2> 9873 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10038 (1428655350140108800)]} 0 0
[junit4:junit4] 2> 9875 T535 C64 P53449 /update {wt=javabin&version=2} {add=[38 (1428655350142205952)]} 0 0
[junit4:junit4] 2> 9875 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10039 (1428655350142205952)]} 0 0
[junit4:junit4] 2> 9878 T514 C63 P53437 /update {wt=javabin&version=2} {add=[39 (1428655350145351680)]} 0 0
[junit4:junit4] 2> 9878 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10039 (1428655350145351680)]} 0 0
[junit4:junit4] 2> 9881 T534 C64 P53449 /update {wt=javabin&version=2} {add=[39 (1428655350147448832)]} 0 1
[junit4:junit4] 2> 9893 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10040 (1428655350160031744)]} 0 1
[junit4:junit4] 2> 9895 T516 C63 P53437 /update {wt=javabin&version=2} {add=[40 (1428655350163177472)]} 0 0
[junit4:junit4] 2> 9895 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10040 (1428655350163177472)]} 0 0
[junit4:junit4] 2> 9897 T537 C64 P53449 /update {wt=javabin&version=2} {add=[40 (1428655350165274624)]} 0 0
[junit4:junit4] 2> 9934 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10041 (1428655350203023360)]} 0 1
[junit4:junit4] 2> 9937 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10041 (1428655350206169088)]} 0 1
[junit4:junit4] 2> 9937 T517 C63 P53437 /update {wt=javabin&version=2} {add=[41 (1428655350207217664)]} 0 0
[junit4:junit4] 2> 9939 T535 C64 P53449 /update {wt=javabin&version=2} {add=[41 (1428655350209314816)]} 0 0
[junit4:junit4] 2> 9959 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10042 (1428655350230286336)]} 0 0
[junit4:junit4] 2> 9962 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10042 (1428655350233432064)]} 0 0
[junit4:junit4] 2> 9963 T514 C63 P53437 /update {wt=javabin&version=2} {add=[42 (1428655350233432064)]} 0 1
[junit4:junit4] 2> 9965 T534 C64 P53449 /update {wt=javabin&version=2} {add=[42 (1428655350236577792)]} 0 0
[junit4:junit4] 2> 10018 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[10041 (-1428655350291103744)]} 0 1
[junit4:junit4] 2> 10020 T533 C64 P53449 /update {wt=javabin&version=2} {delete=[10041 (-1428655350294249472)]} 0 0
[junit4:junit4] 2> 10020 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[41 (-1428655350294249472)]} 0 0
[junit4:junit4] 2> 10022 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10043 (1428655350296346624)]} 0 0
[junit4:junit4] 2> 10022 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[41 (-1428655350296346624)]} 0 0
[junit4:junit4] 2> 10024 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10043 (1428655350298443776)]} 0 0
[junit4:junit4] 2> 10025 T517 C63 P53437 /update {wt=javabin&version=2} {add=[43 (1428655350298443776)]} 0 1
[junit4:junit4] 2> 10027 T535 C64 P53449 /update {wt=javabin&version=2} {add=[43 (1428655350300540928)]} 0 1
[junit4:junit4] 2> 10046 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10044 (1428655350321512448)]} 0 0
[junit4:junit4] 2> 10049 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10044 (1428655350323609600)]} 0 1
[junit4:junit4] 2> 10050 T514 C63 P53437 /update {wt=javabin&version=2} {add=[44 (1428655350324658176)]} 0 1
[junit4:junit4] 2> 10051 T534 C64 P53449 /update {wt=javabin&version=2} {add=[44 (1428655350326755328)]} 0 0
[junit4:junit4] 2> C62_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53458_k%2Fi, base_url=http://127.0.0.1:53458/k/i}
[junit4:junit4] 2> 10079 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53449/k/i/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 10079 T561 C62 P53458 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53458/k/i START replicas=[http://127.0.0.1:53449/k/i/collection1/] nUpdates=100
[junit4:junit4] 2> 10079 T561 C62 P53458 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 10079 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 10079 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 10080 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 10081 T561 C62 P53458 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\tlog\tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 10081 T561 C62 P53458 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53449/k/i/collection1/. core=collection1
[junit4:junit4] 2> 10081 T561 C62 P53458 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 10081 T533 C64 P53449 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 10086 T537 C64 P53449 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 10106 T537 C64 P53449 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1615685 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1db9b4f)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1615685 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1db9b4f)),segFN=segments_2,generation=2,filenames=[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0.si, _0_MockSep_0.doc, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, segments_2, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> 10107 T537 C64 P53449 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0.si, _0_MockSep_0.doc, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, segments_2, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> 10107 T537 C64 P53449 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1
[junit4:junit4] 2> 10108 T537 C64 P53449 oass.SolrIndexSearcher.<init> Opening Searcher@12cbe8c realtime
[junit4:junit4] 2> 10108 T537 C64 P53449 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 10108 T537 C64 P53449 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 10109 T561 C62 P53458 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 10109 T561 C62 P53458 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 10112 T536 C64 P53449 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 10112 T536 C64 P53449 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 10112 T561 C62 P53458 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 10112 T561 C62 P53458 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 10112 T561 C62 P53458 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 10114 T534 C64 P53449 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1
[junit4:junit4] 2> 10114 T534 C64 P53449 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty1\index
[junit4:junit4] 2> 10114 T534 C64 P53449 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 10114 T561 C62 P53458 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 30
[junit4:junit4] 2> 10115 T561 C62 P53458 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667 forceNew:false
[junit4:junit4] 2> 10116 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10116 T561 C62 P53458 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2) fullCopy=true
[junit4:junit4] 2> 10118 T533 C64 P53449 REQ /replication {file=_0_MockSep_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10118 T515 C63 P53437 /update {wt=javabin&version=2} {delete=[10042 (-1428655350397009920)]} 0 0
[junit4:junit4] 2> 10121 T537 C64 P53449 REQ /replication {file=_0_TestBloomFilteredLucene41Postings_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10125 T538 C64 P53449 /update {wt=javabin&version=2} {delete=[10042 (-1428655350400155648)]} 0 4
[junit4:junit4] 2> 10125 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[42 (-1428655350404349952)]} 0 0
[junit4:junit4] 2> 10127 T535 C64 P53449 REQ /replication {file=_0_TestBloomFilteredLucene41Postings_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10129 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10045 (1428655350406447104)]} 0 2
[junit4:junit4] 2> 10129 T536 C64 P53449 /update {wt=javabin&version=2} {delete=[42 (-1428655350408544256)]} 0 0
[junit4:junit4] 2> 10130 T534 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.tib&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10132 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10045 (1428655350410641408)]} 0 1
[junit4:junit4] 2> 10132 T517 C63 P53437 /update {wt=javabin&version=2} {add=[45 (1428655350411689984)]} 0 0
[junit4:junit4] 2> 10133 T537 C64 P53449 REQ /replication {file=_0_TestBloomFilteredLucene41Postings_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10135 T538 C64 P53449 /update {wt=javabin&version=2} {add=[45 (1428655350414835712)]} 0 0
[junit4:junit4] 2> 10136 T535 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.skp&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10139 T536 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.pyl&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10140 T561 C62 P53458 oash.SnapPuller$DirectoryFileFetcher.fetchPackets WARNING No content recieved for file: {name=_0_MockFixedIntBlock_0.pyl, size=0}
[junit4:junit4] 2> 10143 T533 C64 P53449 REQ /replication {file=_0_MockSep_0.skp&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10145 T534 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.tii&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10151 T537 C64 P53449 REQ /replication {file=_0.nvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10154 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10046 (1428655350434758656)]} 0 1
[junit4:junit4] 2> 10156 T538 C64 P53449 REQ /replication {file=_0_MockSep_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10158 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10046 (1428655350437904384)]} 0 1
[junit4:junit4] 2> 10158 T536 C64 P53449 REQ /replication {file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10160 T514 C63 P53437 /update {wt=javabin&version=2} {add=[46 (1428655350440001536)]} 0 0
[junit4:junit4] 2> 10161 T533 C64 P53449 REQ /replication {file=_0.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10162 T534 C64 P53449 /update {wt=javabin&version=2} {add=[46 (1428655350442098688)]} 0 1
[junit4:junit4] 2> 10163 T537 C64 P53449 REQ /replication {file=_0_TestBloomFilteredLucene41Postings_0.blm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10165 T535 C64 P53449 REQ /replication {file=_0_Disk_0.dvdd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10167 T538 C64 P53449 REQ /replication {file=_0_Memory_0.ram&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10170 T536 C64 P53449 REQ /replication {file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10174 T533 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10177 T534 C64 P53449 REQ /replication {file=_0.nvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10179 T537 C64 P53449 REQ /replication {file=_0_Disk_0.dvdm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10182 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10047 (1428655350464118784)]} 0 0
[junit4:junit4] 2> 10182 T535 C64 P53449 REQ /replication {file=_0_MockSep_0.tib&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10184 T538 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.frq&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10185 T536 C64 P53449 /update {wt=javabin&version=2} {add=[10047 (1428655350466215936)]} 0 1
[junit4:junit4] 2> 10186 T516 C63 P53437 /update {wt=javabin&version=2} {add=[47 (1428655350468313088)]} 0 0
[junit4:junit4] 2> 10188 T533 C64 P53449 REQ /replication {file=_0_MockFixedIntBlock_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10190 T537 C64 P53449 REQ /replication {file=_0_MockSep_0.frq&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10190 T534 C64 P53449 /update {wt=javabin&version=2} {add=[47 (1428655350471458816)]} 0 1
[junit4:junit4] 2> 10194 T535 C64 P53449 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10196 T536 C64 P53449 REQ /replication {file=_0_TestBloomFilteredLucene41Postings_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10199 T538 C64 P53449 REQ /replication {file=_0.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10201 T533 C64 P53449 REQ /replication {file=_0_MockSep_0.tii&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10203 T537 C64 P53449 REQ /replication {file=_0_MockSep_0.pyl&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10204 T561 C62 P53458 oash.SnapPuller$DirectoryFileFetcher.fetchPackets WARNING No content recieved for file: {name=_0_MockSep_0.pyl, size=0}
[junit4:junit4] 2> 10206 T534 C64 P53449 REQ /replication {file=_0.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 10206 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 10206 T561 C62 P53458 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 10206 T561 C62 P53458 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130305032514667
[junit4:junit4] 2> 10207 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10207 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10208 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10208 T561 C62 P53458 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 10208 T561 C62 P53458 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 10208 T561 C62 P53458 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 10208 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 10209 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10209 T561 C62 P53458 oasc.SolrCore.getNewIndexDir New index directory detected: old=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/jetty2\index/ new=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554/jetty2\index.20130305032514667
[junit4:junit4] 2> 10212 T561 C62 P53458 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2),segFN=segments_2,generation=2,filenames=[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0_MockSep_0.doc, _0.si, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, segments_2, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> 10212 T561 C62 P53458 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0_MockSep_0.doc, _0.si, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, segments_2, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> 10213 T561 C62 P53458 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 10213 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10213 T561 C62 P53458 oass.SolrIndexSearcher.<init> Opening Searcher@a0f2f8 main
[junit4:junit4] 2> 10213 T560 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a0f2f8 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C88/36)}
[junit4:junit4] 2> 10215 T560 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 10215 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667
[junit4:junit4] 2> 10215 T561 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 10215 T561 C62 P53458 oasc.CachingDirectoryFactory.close Closing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 10215 T561 C62 P53458 oash.SnapPuller$2.preClose removing old index files MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@bd238b lockFactory=org.apache.lucene.store.NativeFSLockFactory@14ad9fb))
[junit4:junit4] 2> 10215 T561 C62 P53458 oasc.CachingDirectoryFactory.closeDirectory Closing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index
[junit4:junit4] 2> 10215 T561 C62 P53458 oash.SnapPuller$2.postClose removing old index directory MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@bd238b lockFactory=org.apache.lucene.store.NativeFSLockFactory@14ad9fb))
[junit4:junit4] 2> 10216 T561 C62 P53458 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 10216 T569 C62 P53458 oasu.UpdateLog$LogReplayer.doReplay WARNING Starting log replay tlog{file=.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\tlog\tlog.0000000000000000000 refcount=2} active=true starting pos=4667
[junit4:junit4] 2> 10217 T569 C62 P53458 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 10217 T569 C62 P53458 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2),segFN=segments_2,generation=2,filenames=[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0_MockSep_0.doc, _0.si, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, segments_2, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2),segFN=segments_3,generation=3,filenames=[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0_MockSep_0.doc, _0.si, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_3]
[junit4:junit4] 2> 10217 T569 C62 P53458 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0_MockSep_0.doc, _0.si, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_3]
[junit4:junit4] 2> 10218 T569 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10218 T569 C62 P53458 oass.SolrIndexSearcher.<init> Opening Searcher@72f262 main
[junit4:junit4] 2> 10219 T569 C62 P53458 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 10219 T560 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72f262 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):C88/36)}
[junit4:junit4] 2> 10220 T560 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667
[junit4:junit4] 2> 10220 T569 C62 P53458 oasu.UpdateLog$LogReplayer.run WARNING Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=4667}
[junit4:junit4] 2> 10220 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 10221 T561 C62 P53458 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 10221 T561 C62 P53458 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 10224 T561 C62 P53458 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 10249 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10048 (1428655350534373376)]} 0 1
[junit4:junit4] 2> 10252 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10048 (1428655350536470528)]} 0 1
[junit4:junit4] 2> 10257 T513 C63 P53437 /update {wt=javabin&version=2} {add=[48 (1428655350542761984)]} 0 0
[junit4:junit4] 2> 10263 T536 C64 P53449 /update {wt=javabin&version=2} {add=[48 (1428655350548004864)]} 0 1
[junit4:junit4] 2> 10268 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[10045 (-1428655350554296320)]} 0 0
[junit4:junit4] 2> 10270 T538 C64 P53449 /update {wt=javabin&version=2} {delete=[10045 (-1428655350556393472)]} 0 0
[junit4:junit4] 2> 10273 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10049 (1428655350558490624)]} 0 1
[junit4:junit4] 2> 10275 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10049 (1428655350560587776)]} 0 1
[junit4:junit4] 2> 10279 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[45 (-1428655350565830656)]} 0 0
[junit4:junit4] 2> 10283 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[45 (-1428655350570024960)]} 0 0
[junit4:junit4] 2> 10286 T517 C63 P53437 /update {wt=javabin&version=2} {add=[49 (1428655350572122112)]} 0 1
[junit4:junit4] 2> 10289 T534 C64 P53449 /update {wt=javabin&version=2} {add=[49 (1428655350576316416)]} 0 0
[junit4:junit4] 2> 10325 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10050 (1428655350613016576)]} 0 1
[junit4:junit4] 2> 10329 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10050 (1428655350618259456)]} 0 0
[junit4:junit4] 2> 10340 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10051 (1428655350628745216)]} 0 2
[junit4:junit4] 2> 10340 T514 C63 P53437 /update {wt=javabin&version=2} {add=[50 (1428655350628745217)]} 0 1
[junit4:junit4] 2> 10342 T538 C64 P53449 /update {wt=javabin&version=2} {add=[10051 (1428655350631890945)]} 0 0
[junit4:junit4] 2> 10342 T536 C64 P53449 /update {wt=javabin&version=2} {add=[50 (1428655350631890944)]} 0 0
[junit4:junit4] 2> 10352 T515 C63 P53437 /update {wt=javabin&version=2} {add=[51 (1428655350642376704)]} 0 0
[junit4:junit4] 2> 10354 T533 C64 P53449 /update {wt=javabin&version=2} {add=[51 (1428655350644473856)]} 0 0
[junit4:junit4] 2> 10377 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10052 (1428655350668591104)]} 0 1
[junit4:junit4] 2> 10379 T537 C64 P53449 /update {wt=javabin&version=2} {add=[10052 (1428655350670688256)]} 0 0
[junit4:junit4] 2> 10387 T517 C63 P53437 /update {wt=javabin&version=2} {add=[52 (1428655350679076864)]} 0 0
[junit4:junit4] 2> 10390 T534 C64 P53449 /update {wt=javabin&version=2} {add=[52 (1428655350682222592)]} 0 0
[junit4:junit4] 2> 10414 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10053 (1428655350707388416)]} 0 0
[junit4:junit4] 2> 10419 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10053 (1428655350712631296)]} 0 0
[junit4:junit4] 2> 10425 T513 C63 P53437 /update {wt=javabin&version=2} {add=[53 (1428655350717874176)]} 0 1
[junit4:junit4] 2> 10428 T538 C64 P53449 /update {wt=javabin&version=2} {add=[53 (1428655350722068480)]} 0 0
[junit4:junit4] 2> 10453 T514 C63 P53437 /update {wt=javabin&version=2} {delete=[10048 (-1428655350748282880)]} 0 1
[junit4:junit4] 2> 10456 T536 C64 P53449 /update {wt=javabin&version=2} {delete=[10048 (-1428655350750380032)]} 0 1
[junit4:junit4] 2> 10458 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10054 (1428655350753525760)]} 0 0
[junit4:junit4] 2> 10461 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10054 (1428655350755622912)]} 0 1
[junit4:junit4] 2> 10463 T516 C63 P53437 /update {wt=javabin&version=2} {delete=[48 (-1428655350758768640)]} 0 0
[junit4:junit4] 2> 10465 T537 C64 P53449 /update {wt=javabin&version=2} {delete=[48 (-1428655350760865792)]} 0 0
[junit4:junit4] 2> 10467 T517 C63 P53437 /update {wt=javabin&version=2} {add=[54 (1428655350762962944)]} 0 0
[junit4:junit4] 2> 10469 T534 C64 P53449 /update {wt=javabin&version=2} {add=[54 (1428655350765060096)]} 0 0
[junit4:junit4] 2> 10534 T518 C63 P53437 /update {wt=javabin&version=2} {add=[10055 (1428655350833217536)]} 0 1
[junit4:junit4] 2> 10537 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10055 (1428655350836363264)]} 0 0
[junit4:junit4] 2> 10543 T513 C63 P53437 /update {wt=javabin&version=2} {add=[55 (1428655350842654720)]} 0 1
[junit4:junit4] 2> 10545 T536 C64 P53449 /update {wt=javabin&version=2} {add=[55 (1428655350844751872)]} 0 0
[junit4:junit4] 2> 10581 T514 C63 P53437 /update {wt=javabin&version=2} {add=[10056 (1428655350882500608)]} 0 0
[junit4:junit4] 2> 10584 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10056 (1428655350884597760)]} 0 1
[junit4:junit4] 2> 10588 T515 C63 P53437 /update {wt=javabin&version=2} {add=[56 (1428655350889840640)]} 0 0
[junit4:junit4] 2> 10592 T537 C64 P53449 /update {wt=javabin&version=2} {add=[56 (1428655350894034944)]} 0 0
[junit4:junit4] 2> 10656 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10057 (1428655350960095232)]} 0 1
[junit4:junit4] 2> 10658 T534 C64 P53449 /update {wt=javabin&version=2} {add=[10057 (1428655350963240960)]} 0 0
[junit4:junit4] 2> 10663 T518 C63 P53437 /update {wt=javabin&version=2} {add=[57 (1428655350967435264)]} 0 1
[junit4:junit4] 2> 10665 T538 C64 P53449 /update {wt=javabin&version=2} {add=[57 (1428655350969532416)]} 0 1
[junit4:junit4] 2> 10715 T513 C63 P53437 /update {wt=javabin&version=2} {add=[10058 (1428655351023009792)]} 0 0
[junit4:junit4] 2> 10718 T535 C64 P53449 /update {wt=javabin&version=2} {add=[10058 (1428655351025106944)]} 0 1
[junit4:junit4] 2> 10721 T514 C63 P53437 /update {wt=javabin&version=2} {add=[58 (1428655351029301248)]} 0 0
[junit4:junit4] 2> 10723 T536 C64 P53449 /update {wt=javabin&version=2} {add=[58 (1428655351031398400)]} 0 0
[junit4:junit4] 2> 10750 T523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 10750 T523 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:53458_k%2Fi",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53458/k/i"}
[junit4:junit4] 2> 10759 T529 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> 10759 T558 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> 10760 T542 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> 10760 T515 C63 P53437 /update {wt=javabin&version=2} {add=[10059 (1428655351069147136)]} 0 1
[junit4:junit4] 2> 10760 T522 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> 10763 T533 C64 P53449 /update {wt=javabin&version=2} {add=[10059 (1428655351072292864)]} 0 1
[junit4:junit4] 2> 10767 T517 C63 P53437 /update {wt=javabin&version=2} {add=[59 (1428655351076487168)]} 0 1
[junit4:junit4] 2> C62_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53458_k%2Fi, base_url=http://127.0.0.1:53458/k/i}
[junit4:junit4] 2> 10778 T550 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1428655351079632896)]} 0 6
[junit4:junit4] 2> 10779 T537 C64 P53449 /update {wt=javabin&version=2} {add=[59 (1428655351079632896)]} 0 10
[junit4:junit4] 2> 10787 T500 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10787 T500 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 10794 T500 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@825b44
[junit4:junit4] 2> 10798 T500 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667
[junit4:junit4] 2> 10798 T500 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10798 T500 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667
[junit4:junit4] 2> 10799 T500 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2
[junit4:junit4] 2> 10802 T516 C63 P53437 /update {wt=javabin&version=2} {add=[10060 (1428655351113187328)]} 0 1
[junit4:junit4] 2> 10803 T500 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=1,adds=1,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=33,cumulative_deletesById=16,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 10805 T500 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 10805 T500 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 10805 T500 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 10807 T552 C62 P53458 /update {distrib.from=http://127.0.0.1:53449/k/i/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {} 0 0
[junit4:junit4] 2> 10807 T500 C62 P53458 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2),segFN=segments_3,generation=3,filenames=[_0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _0.nvd, _0_MockSep_0.doc, _0.si, _0.fnm, _0_Disk_0.dvdd, _0_TestBloomFilteredLucene41Postings_0.blm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockFixedIntBlock_0.frq, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.doc, _0_TestBloomFilteredLucene41Postings_0.doc, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2),segFN=segments_4,generation=4,filenames=[_1_TestBloomFilteredLucene41Postings_0.pos, _0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _1_MockFixedIntBlock_0.pyl, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _1.fnm, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _1_MockSep_0.doc, _1_MockSep_0.pyl, _1.nvm, _1_MockSep_0.skp, _0.fnm, _0_TestBloomFilteredLucene41Postings_0.blm, _1_MockFixedIntBlock_0.frq, _0_Memory_0.ram, _1_MockSep_0.tib, _1.nvd, _0_1.del, _0_MockFixedIntBlock_0.pos, _1_TestBloomFilteredLucene41Postings_0.doc, _1_MockSep_0.tii, _1.fdx, _1_MockFixedIntBlock_0.skp, _1.fdt, _1_MockFixedIntBlock_0.pos, _1_MockSep_0.frq, _1_TestBloomFilteredLucene41Postings_0.tim, _1_MockFixedIntBlock_0.doc, _1_TestBloomFilteredLucene41Postings_0.tip, _1_Memory_0.ram, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0.nvd, _0.si, _0_MockSep_0.doc, _1_MockFixedIntBlock_0.tii, _0_Disk_0.dvdd, _1_MockSep_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.frq, _1_TestBloomFilteredLucene41Postings_0.blm, _1_Disk_0.dvdd, _0_MockFixedIntBlock_0.doc, _1.si, _1_MockFixedIntBlock_0.tib, _0_MockSep_0.frq, _0_TestBloomFilteredLucene41Postings_0.doc, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _1_Disk_0.dvdm, _0.fdt, segments_4]
[junit4:junit4] 2> 10808 T552 C62 P53458 oasc.SolrException.log SEVERE java.lang.RuntimeException: SolrCoreState already closed
[junit4:junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:84)
[junit4:junit4] 2> at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:153)
[junit4:junit4] 2> at org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:69)
[junit4:junit4] 2> at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:51)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:451)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:587)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:346)
[junit4:junit4] 2> at org.apache.solr.update.processor.LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:100)
[junit4:junit4] 2> at org.apache.solr.handler.loader.XMLLoader.processUpdate(XMLLoader.java:246)
[junit4:junit4] 2> at org.apache.solr.handler.loader.XMLLoader.load(XMLLoader.java:173)
[junit4:junit4] 2> at org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:92)
[junit4:junit4] 2> at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:74)
[junit4:junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1811)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:583)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:293)
[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:125)
[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> 10809 T500 C62 P53458 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_1_TestBloomFilteredLucene41Postings_0.pos, _0_MockSep_0.pos, _0_TestBloomFilteredLucene41Postings_0.tim, _1_MockFixedIntBlock_0.pyl, _0_TestBloomFilteredLucene41Postings_0.tip, _0_MockFixedIntBlock_0.tib, _0_TestBloomFilteredLucene41Postings_0.pos, _1.fnm, _0_MockSep_0.skp, _0_MockFixedIntBlock_0.tii, _1_MockSep_0.doc, _1_MockSep_0.pyl, _1.nvm, _1_MockSep_0.skp, _0.fnm, _0_TestBloomFilteredLucene41Postings_0.blm, _1_MockFixedIntBlock_0.frq, _0_Memory_0.ram, _1_MockSep_0.tib, _1.nvd, _0_1.del, _0_MockFixedIntBlock_0.pos, _1_TestBloomFilteredLucene41Postings_0.doc, _1_MockSep_0.tii, _1.fdx, _1_MockFixedIntBlock_0.skp, _1.fdt, _1_MockFixedIntBlock_0.pos, _1_MockSep_0.frq, _1_TestBloomFilteredLucene41Postings_0.tim, _1_MockFixedIntBlock_0.doc, _1_TestBloomFilteredLucene41Postings_0.tip, _1_Memory_0.ram, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0.nvd, _0.si, _0_MockSep_0.doc, _1_MockFixedIntBlock_0.tii, _0_Disk_0.dvdd, _1_MockSep_0.pos, _0.nvm, _0_Disk_0.dvdm, _0_MockSep_0.tib, _0_MockFixedIntBlock_0.frq, _1_TestBloomFilteredLucene41Postings_0.blm, _1_Disk_0.dvdd, _0_MockFixedIntBlock_0.doc, _1.si, _1_MockFixedIntBlock_0.tib, _0_MockSep_0.frq, _0_TestBloomFilteredLucene41Postings_0.doc, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _1_Disk_0.dvdm, _0.fdt, segments_4]
[junit4:junit4] 2> 10809 T552 C62 P53458 oasc.SolrException.log SEVERE null:java.lang.RuntimeException: SolrCoreState already closed
[junit4:junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:84)
[junit4:junit4] 2> at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:153)
[junit4:junit4] 2> at org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:69)
[junit4:junit4] 2> at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:51)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:451)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:587)
[junit4:junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:346)
[junit4:junit4] 2> at org.apache.solr.update.processor.LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:100)
[junit4:junit4] 2> at org.apache.solr.handler.loader.XMLLoader.processUpdate(XMLLoader.java:246)
[junit4:junit4] 2> at org.apache.solr.handler.loader.XMLLoader.load(XMLLoader.java:173)
[junit4:junit4] 2> at org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:92)
[junit4:junit4] 2> at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:74)
[junit4:junit4] 2> at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.execute(SolrCore.java:1811)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:583)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:293)
[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:125)
[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> 10811 T552 C62 P53458 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@825b44
[junit4:junit4] 2> 10811 T552 C62 P53458 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=1,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=33,cumulative_deletesById=16,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 10813 T500 C62 P53458 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667
[junit4:junit4] 2> 10814 T500 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 10814 T552 C62 P53458 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 10814 T500 oasc.CachingDirectoryFactory.close Releasing directory:C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.RecoveryZkTest-1362471904554\jetty2\index.20130305032514667
[junit4:junit4] 2> 10815 T505 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d39a7652f0008
[junit4:junit4] 2> 10817 T529 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> 10818 T502 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:53466 which had sessionid 0x13d39a7652f0008
[junit4:junit4] 2> 10818 T542 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> 10818 T522 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> 10818 T500 oaz.ZooKeeper.close Session: 0x13d39a7652f0008 closed
[junit4:junit4] 2> 10820 T518 C63 P53437 /update {wt=javabin&version=2} {add=[60 (1428655351132061696)]} 0 1
[junit4:junit4] 2> 10820 T534 C64 P53449 oasc.SolrException.log SEVERE shard update error StdNode: http://127.0.0.1:53458/k/i/collection1/:org.apache.solr.common.SolrException: Server at http://127.0.0.1:53458/k/i/collection1 returned non ok status:500, message:Server Error
[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> 10821 T534 C64 P53449 oasup.DistributedUpdateProcessor.doFinish try and ask http://127.0.0.1:53458/k/i to recover
[junit4:junit4] 2> 10821 T534 C64 P53449 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 10831 T542 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 10831 T522 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 10831 T529 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 10832 T538 C64 P53449 oasc.SolrException.log SEVERE shard update error StdNode: http://127.0.0.1:53458/k/i/collection1/:org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:53458/k/i/collection1
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:416)
[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> Caused by: org.apache.http.NoHttpResponseException: The target server failed to respond
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:95)
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
[junit4:junit4] 2> at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
[junit4:junit4] 2> at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
[junit4:junit4] 2> at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
[junit4:junit4] 2> at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
[junit4:junit4] 2> at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:717)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:522)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
[junit4:junit4] 2> ... 11 more
[junit4:junit4] 2>
[junit4:junit4] 2> 10833 T500 oejsh.ContextHandler.doStop stopped o.e.j
[...truncated too long message...]
timestamp=MockFixedIntBlock(blockSize=1973), a_t=MockFixedIntBlock(blockSize=1973), range_facet_sl=PostingsFormat(name=TestBloomFilteredLucene41Postings), range_facet_si=PostingsFormat(name=MockSep), other_tl1=MockFixedIntBlock(blockSize=1973), multiDefault=PostingsFormat(name=MockSep), a_si=PostingsFormat(name=MockSep)}, docValues:{timestamp=DocValuesFormat(name=Disk)}, sim=DefaultSimilarity, locale=mt, timezone=SystemV/EST5
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Sun Microsystems Inc. 1.6.0_41 (32-bit)/cpus=2,threads=3,free=21273712,total=60461056
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestXIncludeConfig, SpatialFilterTest, ResponseLogComponentTest, TestElisionMultitermQuery, CurrencyFieldXmlFileTest, TestSurroundQueryParser, SystemInfoHandlerTest, TestNumberUtils, TestLMJelinekMercerSimilarityFactory, BasicZkTest, LegacyHTMLStripCharFilterTest, BadIndexSchemaTest, SignatureUpdateProcessorFactoryTest, SOLR749Test, DateFieldTest, UniqFieldsUpdateProcessorFactoryTest, UnloadDistributedZkTest, DateMathParserTest, TestAtomicUpdateErrorCases, TestPerFieldSimilarity, TestRecovery, TestJoin, ClusterStateTest, ScriptEngineTest, IndexReaderFactoryTest, TestQueryTypes, SolrInfoMBeanTest, DOMUtilTest, QueryElevationComponentTest, DocValuesMultiTest, TestComponentsName, SimplePostToolTest, LoggingHandlerTest, TestRemoteStreaming, DirectUpdateHandlerTest, OpenExchangeRatesOrgProviderTest, PathHierarchyTokenizerFactoryTest, TestHashPartitioner, MBeansHandlerTest, TestOmitPositions, SampleTest, TestSolr4Spatial, TestWriterPerf, SearchHandlerTest, TestRealTimeGet, TestSolrDeletionPolicy1, EchoParamsTest, XsltUpdateRequestHandlerTest, TestLazyCores, RecoveryZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.seed=C42994DEB8FC539A -Dtests.slow=true -Dtests.locale=mt -Dtests.timezone=SystemV/EST5 -Dtests.file.encoding=UTF-8
[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=559, name=coreLoadExecutor-479-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:33)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:267)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:223)
[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:733)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:874)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.create(CoreContainer.java:957)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:580)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:575)
[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@35fcce lockFactory=org.apache.lucene.store.NativeFSLockFactory@1539062)
[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=561, 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:33)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:267)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:223)
[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@3382f lockFactory=org.apache.lucene.store.NativeFSLockFactory@16b16f2)
[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 31.08s, 1 test, 2 errors <<< FAILURES!
[...truncated 664 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:381: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:361: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:183: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:449: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1213: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:877: There were test failures: 261 suites, 1105 tests, 2 suite-level errors, 18 ignored (12 assumptions)
Total time: 66 minutes 6 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.6.0_41 -client -XX:+UseSerialGC
Email was triggered for: Failure
Sending email for trigger: Failure