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/06 04:03:40 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_15) - Build #
4588 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4588/
Java: 32bit/jdk1.7.0_15 -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=2959, name=coreLoadExecutor-2287-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=2959, name=coreLoadExecutor-2287-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1567)
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:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@9748d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1836c77)
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=2961, 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=2961, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1567)
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@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9262 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 0 T2900 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /u/
[junit4:junit4] 2> 5 T2900 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-RecoveryZkTest-1362538766356
[junit4:junit4] 2> 5 T2900 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 7 T2901 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 9 T2901 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 9 T2901 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 9 T2901 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 9 T2901 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 14 T2901 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 106 T2900 oasc.ZkTestServer.run start zk server on port:35622
[junit4:junit4] 2> 107 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5f0b62
[junit4:junit4] 2> 108 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108 T2906 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 109 T2906 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 109 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45446
[junit4:junit4] 2> 109 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45446
[junit4:junit4] 2> 109 T2904 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 282 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0000 with negotiated timeout 10000 for client /127.0.0.1:45446
[junit4:junit4] 2> 283 T2906 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0000, negotiated timeout = 10000
[junit4:junit4] 2> 283 T2907 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f0b62 name:ZooKeeperConnection Watcher:127.0.0.1:35622 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 284 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 284 T2900 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 288 T2905 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3da3a01d0000
[junit4:junit4] 2> 289 T2900 oaz.ZooKeeper.close Session: 0x13d3da3a01d0000 closed
[junit4:junit4] 2> 289 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4f3df
[junit4:junit4] 2> 290 T2907 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 291 T2908 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 291 T2908 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 292 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 295 T2902 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:45446 which had sessionid 0x13d3da3a01d0000
[junit4:junit4] 2> 296 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45447
[junit4:junit4] 2> 296 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45447
[junit4:junit4] 2> 297 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0001 with negotiated timeout 10000 for client /127.0.0.1:45447
[junit4:junit4] 2> 298 T2908 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0001, negotiated timeout = 10000
[junit4:junit4] 2> 298 T2909 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f3df name:ZooKeeperConnection Watcher:127.0.0.1:35622/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 298 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 299 T2900 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 304 T2900 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 306 T2900 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 307 T2900 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 309 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 310 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 313 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 314 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 317 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 317 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 319 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 319 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 322 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 322 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 325 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 326 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 327 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 328 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 330 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 331 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 335 T2900 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 335 T2900 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 339 T2905 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3da3a01d0001
[junit4:junit4] 2> 340 T2902 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:45447 which had sessionid 0x13d3da3a01d0001
[junit4:junit4] 2> 341 T2909 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 341 T2900 oaz.ZooKeeper.close Session: 0x13d3da3a01d0001 closed
[junit4:junit4] 2> 406 T2900 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 408 T2900 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60402
[junit4:junit4] 2> 409 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 410 T2900 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 410 T2900 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693
[junit4:junit4] 2> 410 T2900 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/solr.xml
[junit4:junit4] 2> 411 T2900 oasc.CoreContainer.<init> New CoreContainer 28971482
[junit4:junit4] 2> 411 T2900 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/'
[junit4:junit4] 2> 412 T2900 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/'
[junit4:junit4] 2> 433 T2900 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 434 T2900 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 434 T2900 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 435 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 435 T2900 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 436 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 436 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 437 T2900 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 437 T2900 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 438 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 461 T2900 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 479 T2900 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35622/solr
[junit4:junit4] 2> 480 T2900 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 480 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1b4e5b1
[junit4:junit4] 2> 485 T2919 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 485 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 486 T2919 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 486 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45448
[junit4:junit4] 2> 487 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45448
[junit4:junit4] 2> 488 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0002 with negotiated timeout 20000 for client /127.0.0.1:45448
[junit4:junit4] 2> 489 T2919 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0002, negotiated timeout = 20000
[junit4:junit4] 2> 489 T2920 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b4e5b1 name:ZooKeeperConnection Watcher:127.0.0.1:35622 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 492 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 494 T2905 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3da3a01d0002
[junit4:junit4] 2> 494 T2902 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:45448 which had sessionid 0x13d3da3a01d0002
[junit4:junit4] 2> 494 T2900 oaz.ZooKeeper.close Session: 0x13d3da3a01d0002 closed
[junit4:junit4] 2> 495 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 496 T2920 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 498 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@189c3a6
[junit4:junit4] 2> 499 T2921 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 499 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 499 T2921 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 499 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45449
[junit4:junit4] 2> 500 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45449
[junit4:junit4] 2> 500 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0003 with negotiated timeout 20000 for client /127.0.0.1:45449
[junit4:junit4] 2> 500 T2921 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0003, negotiated timeout = 20000
[junit4:junit4] 2> 501 T2922 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@189c3a6 name:ZooKeeperConnection Watcher:127.0.0.1:35622/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 501 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 503 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 504 T2900 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 505 T2900 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60402_u
[junit4:junit4] 2> 506 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:60402_u Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:60402_u
[junit4:junit4] 2> 506 T2900 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60402_u
[junit4:junit4] 2> 509 T2900 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 513 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 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> 514 T2900 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 516 T2900 oasc.Overseer.start Overseer (id=89295340592496643-127.0.0.1:60402_u-n_0000000000) starting
[junit4:junit4] 2> 517 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 517 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 518 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 519 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 519 T2924 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 520 T2900 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 522 T2900 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 524 T2923 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 527 T2925 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/collection1
[junit4:junit4] 2> 527 T2925 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 527 T2925 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 528 T2925 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 529 T2925 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/collection1/'
[junit4:junit4] 2> 530 T2925 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/collection1/lib/README' to classloader
[junit4:junit4] 2> 530 T2925 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 578 T2925 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 631 T2925 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 634 T2925 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 638 T2925 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1192 T2925 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1201 T2925 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1215 T2925 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1231 T2925 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1236 T2925 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1241 T2925 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1242 T2925 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1242 T2925 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1243 T2925 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1243 T2925 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1244 T2925 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1244 T2925 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1362538766693/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data/
[junit4:junit4] 2> 1244 T2925 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@262d42
[junit4:junit4] 2> 1245 T2925 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1245 T2925 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data forceNew:false
[junit4:junit4] 2> 1245 T2925 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data
[junit4:junit4] 2> 1246 T2925 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data/index/
[junit4:junit4] 2> 1246 T2925 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1246 T2925 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data/index forceNew:false
[junit4:junit4] 2> 1247 T2925 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ec02aa lockFactory=org.apache.lucene.store.NativeFSLockFactory@c7370b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1248 T2925 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1248 T2925 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data/index
[junit4:junit4] 2> 1249 T2925 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1250 T2925 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1250 T2925 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1250 T2925 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1251 T2925 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1251 T2925 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1251 T2925 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1252 T2925 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1252 T2925 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1256 T2925 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1261 T2925 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data
[junit4:junit4] 2> 1261 T2925 oass.SolrIndexSearcher.<init> Opening Searcher@12ece7d main
[junit4:junit4] 2> 1262 T2925 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data/tlog
[junit4:junit4] 2> 1262 T2925 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1263 T2925 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1266 T2925 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data
[junit4:junit4] 2> 1267 T2926 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12ece7d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1268 T2925 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1268 T2925 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1268 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 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> 2030 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2030 T2923 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:60402_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60402/u"}
[junit4:junit4] 2> 2031 T2923 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2031 T2923 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2031 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 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> 2034 T2922 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> 2270 T2925 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2270 T2925 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60402/u collection:control_collection shard:shard1
[junit4:junit4] 2> 2271 T2925 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2277 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 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> 2278 T2925 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2280 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2281 T2925 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2281 T2925 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2281 T2925 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60402/u/collection1/
[junit4:junit4] 2> 2282 T2925 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2282 T2925 oasc.SyncStrategy.syncToMe http://127.0.0.1:60402/u/collection1/ has no replicas
[junit4:junit4] 2> 2282 T2925 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60402/u/collection1/
[junit4:junit4] 2> 2282 T2925 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2286 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3537 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3544 T2922 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> 3589 T2925 oasc.ZkController.register We are http://127.0.0.1:60402/u/collection1/ and leader is http://127.0.0.1:60402/u/collection1/
[junit4:junit4] 2> 3589 T2925 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60402/u
[junit4:junit4] 2> 3590 T2925 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3590 T2925 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3590 T2925 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3591 T2925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3595 T2900 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3595 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3596 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3599 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3600 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1399961
[junit4:junit4] 2> 3601 T2928 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3601 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45450
[junit4:junit4] 2> 3602 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3602 T2928 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 3603 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45450
[junit4:junit4] 2> 3605 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0004 with negotiated timeout 10000 for client /127.0.0.1:45450
[junit4:junit4] 2> 3605 T2928 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0004, negotiated timeout = 10000
[junit4:junit4] 2> 3614 T2929 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1399961 name:ZooKeeperConnection Watcher:127.0.0.1:35622/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3614 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3616 T2900 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3623 T2900 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3689 T2900 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3691 T2900 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59746
[junit4:junit4] 2> 3692 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3692 T2900 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3692 T2900 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974
[junit4:junit4] 2> 3693 T2900 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/solr.xml
[junit4:junit4] 2> 3693 T2900 oasc.CoreContainer.<init> New CoreContainer 18970626
[junit4:junit4] 2> 3693 T2900 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/'
[junit4:junit4] 2> 3694 T2900 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/'
[junit4:junit4] 2> 3725 T2900 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3726 T2900 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3726 T2900 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3727 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3727 T2900 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3728 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3728 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3729 T2900 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3729 T2900 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3730 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3742 T2900 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3767 T2900 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35622/solr
[junit4:junit4] 2> 3768 T2900 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3768 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@104e21b
[junit4:junit4] 2> 3769 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3769 T2939 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3776 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45451
[junit4:junit4] 2> 3776 T2939 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 3778 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45451
[junit4:junit4] 2> 3779 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0005 with negotiated timeout 20000 for client /127.0.0.1:45451
[junit4:junit4] 2> 3779 T2939 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0005, negotiated timeout = 20000
[junit4:junit4] 2> 3780 T2940 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@104e21b name:ZooKeeperConnection Watcher:127.0.0.1:35622 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3780 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3782 T2905 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3da3a01d0005
[junit4:junit4] 2> 3784 T2902 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:45451 which had sessionid 0x13d3da3a01d0005
[junit4:junit4] 2> 3784 T2940 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3784 T2900 oaz.ZooKeeper.close Session: 0x13d3da3a01d0005 closed
[junit4:junit4] 2> 3785 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3788 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@161d46d
[junit4:junit4] 2> 3789 T2941 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3790 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45452
[junit4:junit4] 2> 3790 T2941 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 3791 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45452
[junit4:junit4] 2> 3793 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3793 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0006 with negotiated timeout 20000 for client /127.0.0.1:45452
[junit4:junit4] 2> 3793 T2941 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0006, negotiated timeout = 20000
[junit4:junit4] 2> 3794 T2942 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@161d46d name:ZooKeeperConnection Watcher:127.0.0.1:35622/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3794 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3795 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3796 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3797 T2900 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4798 T2900 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59746_u
[junit4:junit4] 2> 4799 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59746_u Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59746_u
[junit4:junit4] 2> 4800 T2900 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59746_u
[junit4:junit4] 2> 4803 T2929 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4803 T2942 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4803 T2922 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4803 T2922 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> 4808 T2943 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/collection1
[junit4:junit4] 2> 4808 T2943 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4809 T2943 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4809 T2943 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4810 T2943 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/collection1/'
[junit4:junit4] 2> 4810 T2943 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/collection1/lib/README' to classloader
[junit4:junit4] 2> 4811 T2943 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4862 T2943 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 4921 T2943 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4923 T2943 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4946 T2943 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5048 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5048 T2923 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:60402_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60402/u"}
[junit4:junit4] 2> 5053 T2922 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> 5053 T2929 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> 5053 T2942 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> 5590 T2943 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5597 T2943 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5600 T2943 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5616 T2943 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5620 T2943 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5623 T2943 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5624 T2943 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5625 T2943 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5625 T2943 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5626 T2943 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5626 T2943 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5626 T2943 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1362538769974/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/
[junit4:junit4] 2> 5627 T2943 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@262d42
[junit4:junit4] 2> 5627 T2943 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5628 T2943 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1 forceNew:false
[junit4:junit4] 2> 5628 T2943 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1
[junit4:junit4] 2> 5628 T2943 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/index/
[junit4:junit4] 2> 5629 T2943 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5629 T2943 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/index forceNew:false
[junit4:junit4] 2> 5630 T2943 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12c961d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1962ee1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5631 T2943 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5631 T2943 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/index
[junit4:junit4] 2> 5633 T2943 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5633 T2943 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5633 T2943 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5634 T2943 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5634 T2943 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5635 T2943 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5635 T2943 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5635 T2943 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5636 T2943 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5638 T2943 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5641 T2943 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1
[junit4:junit4] 2> 5642 T2943 oass.SolrIndexSearcher.<init> Opening Searcher@1d42521 main
[junit4:junit4] 2> 5642 T2943 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/tlog
[junit4:junit4] 2> 5642 T2943 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5643 T2943 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5647 T2944 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d42521 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5649 T2943 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5649 T2943 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6557 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6558 T2923 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:59746_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59746/u"}
[junit4:junit4] 2> 6558 T2923 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6558 T2923 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6585 T2922 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> 6585 T2942 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> 6585 T2929 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> 6650 T2943 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6651 T2943 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59746/u collection:collection1 shard:shard1
[junit4:junit4] 2> 6651 T2943 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 6655 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0006 type:delete cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 6656 T2943 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 6656 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6657 T2943 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 6657 T2943 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 6658 T2943 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59746/u/collection1/
[junit4:junit4] 2> 6658 T2943 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 6658 T2943 oasc.SyncStrategy.syncToMe http://127.0.0.1:59746/u/collection1/ has no replicas
[junit4:junit4] 2> 6658 T2943 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59746/u/collection1/
[junit4:junit4] 2> 6658 T2943 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 6661 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8087 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8092 T2922 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> 8092 T2942 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> 8092 T2929 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> 8114 T2943 oasc.ZkController.register We are http://127.0.0.1:59746/u/collection1/ and leader is http://127.0.0.1:59746/u/collection1/
[junit4:junit4] 2> 8115 T2943 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59746/u
[junit4:junit4] 2> 8115 T2943 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8115 T2943 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8115 T2943 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8116 T2943 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8117 T2900 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 8118 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8118 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8178 T2900 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8179 T2900 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46739
[junit4:junit4] 2> 8180 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8180 T2900 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8180 T2900 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473
[junit4:junit4] 2> 8181 T2900 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/solr.xml
[junit4:junit4] 2> 8181 T2900 oasc.CoreContainer.<init> New CoreContainer 12303834
[junit4:junit4] 2> 8182 T2900 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/'
[junit4:junit4] 2> 8182 T2900 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/'
[junit4:junit4] 2> 8199 T2900 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8200 T2900 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8200 T2900 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8200 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8201 T2900 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8201 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8201 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8201 T2900 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8202 T2900 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8202 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8218 T2900 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8229 T2900 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35622/solr
[junit4:junit4] 2> 8230 T2900 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8230 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@147e91c
[junit4:junit4] 2> 8231 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8231 T2955 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8232 T2955 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 8232 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45463
[junit4:junit4] 2> 8232 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45463
[junit4:junit4] 2> 8233 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0007 with negotiated timeout 20000 for client /127.0.0.1:45463
[junit4:junit4] 2> 8233 T2955 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0007, negotiated timeout = 20000
[junit4:junit4] 2> 8233 T2956 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@147e91c name:ZooKeeperConnection Watcher:127.0.0.1:35622 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8233 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8235 T2905 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3da3a01d0007
[junit4:junit4] 2> 8235 T2956 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8235 T2902 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:45463 which had sessionid 0x13d3da3a01d0007
[junit4:junit4] 2> 8235 T2900 oaz.ZooKeeper.close Session: 0x13d3da3a01d0007 closed
[junit4:junit4] 2> 8236 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8238 T2900 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35622/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@14afaae
[junit4:junit4] 2> 8239 T2957 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35622. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8239 T2900 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8239 T2957 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35622, initiating session
[junit4:junit4] 2> 8240 T2902 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:45464
[junit4:junit4] 2> 8240 T2902 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:45464
[junit4:junit4] 2> 8240 T2904 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3da3a01d0008 with negotiated timeout 20000 for client /127.0.0.1:45464
[junit4:junit4] 2> 8240 T2957 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35622, sessionid = 0x13d3da3a01d0008, negotiated timeout = 20000
[junit4:junit4] 2> 8241 T2958 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14afaae name:ZooKeeperConnection Watcher:127.0.0.1:35622/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8241 T2900 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8242 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8243 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8244 T2900 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9246 T2900 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46739_u
[junit4:junit4] 2> 9246 T2905 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3da3a01d0008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:46739_u Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:46739_u
[junit4:junit4] 2> 9247 T2900 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46739_u
[junit4:junit4] 2> 9249 T2929 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> 9250 T2942 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9250 T2922 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9250 T2942 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> 9250 T2958 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9251 T2929 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9250 T2922 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> 9255 T2959 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/collection1
[junit4:junit4] 2> 9255 T2959 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9256 T2959 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9256 T2959 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9257 T2959 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/collection1/'
[junit4:junit4] 2> 9258 T2959 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/collection1/lib/README' to classloader
[junit4:junit4] 2> 9258 T2959 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9286 T2959 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9323 T2959 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9324 T2959 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9328 T2959 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9596 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9596 T2923 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:59746_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59746/u"}
[junit4:junit4] 2> 9599 T2929 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> 9599 T2958 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> 9599 T2922 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> 9599 T2942 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> 9759 T2959 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9765 T2959 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9768 T2959 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9777 T2959 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9780 T2959 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9782 T2959 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9783 T2959 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9783 T2959 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9784 T2959 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9784 T2959 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9785 T2959 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9785 T2959 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/
[junit4:junit4] 2> 9785 T2959 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@262d42
[junit4:junit4] 2> 9786 T2959 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9786 T2959 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2 forceNew:false
[junit4:junit4] 2> 9787 T2959 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 9787 T2959 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index/
[junit4:junit4] 2> 9787 T2959 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9787 T2959 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index forceNew:false
[junit4:junit4] 2> 9788 T2959 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20660e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1578229),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9788 T2959 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9789 T2959 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 9790 T2959 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9790 T2959 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9791 T2959 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9791 T2959 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9792 T2959 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9792 T2959 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9792 T2959 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9793 T2959 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9793 T2959 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9795 T2959 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9797 T2959 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 9798 T2959 oass.SolrIndexSearcher.<init> Opening Searcher@181a4fc main
[junit4:junit4] 2> 9798 T2959 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/tlog
[junit4:junit4] 2> 9798 T2959 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9799 T2959 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9803 T2960 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@181a4fc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9805 T2959 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9805 T2959 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11104 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11105 T2923 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:46739_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46739/u"}
[junit4:junit4] 2> 11105 T2923 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11106 T2923 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11262 T2929 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> 11262 T2958 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> 11262 T2942 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> 11262 T2922 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> 11807 T2959 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11807 T2959 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46739/u collection:collection1 shard:shard1
[junit4:junit4] 2> 11810 T2959 oasc.ZkController.register We are http://127.0.0.1:46739/u/collection1/ and leader is http://127.0.0.1:59746/u/collection1/
[junit4:junit4] 2> 11811 T2959 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46739/u
[junit4:junit4] 2> 11811 T2959 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11811 T2959 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C445 name=collection1 org.apache.solr.core.SolrCore@4c0224 url=http://127.0.0.1:46739/u/collection1 node=127.0.0.1:46739_u C445_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46739_u, base_url=http://127.0.0.1:46739/u}
[junit4:junit4] 2> 11811 T2961 C445 P46739 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11812 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11812 T2959 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11812 T2961 C445 P46739 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11813 T2961 C445 P46739 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11813 T2900 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 11813 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11814 T2900 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11816 T2961 C445 P46739 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11817 T2900 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C446 name=collection1 org.apache.solr.core.SolrCore@1ac3951 url=http://127.0.0.1:60402/u/collection1 node=127.0.0.1:60402_u C446_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:60402_u, base_url=http://127.0.0.1:60402/u, leader=true}
[junit4:junit4] 2> 11824 T2916 C446 P60402 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/control/data
[junit4:junit4] 2> 11825 T2916 C446 P60402 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ec02aa lockFactory=org.apache.lucene.store.NativeFSLockFactory@c7370b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11825 T2916 C446 P60402 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11827 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[1 (1428725461863628800)]} 0 3
[junit4:junit4] 2> 11827 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10001 (1428725461863628801)]} 0 3
[junit4:junit4] 2> ASYNC NEW_CORE C447 name=collection1 org.apache.solr.core.SolrCore@8608f url=http://127.0.0.1:59746/u/collection1 node=127.0.0.1:59746_u C447_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59746_u, base_url=http://127.0.0.1:59746/u, leader=true}
[junit4:junit4] 2> 11834 T2935 C447 P59746 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1
[junit4:junit4] 2> 11835 T2935 C447 P59746 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12c961d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1962ee1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11835 T2935 C447 P59746 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11837 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[1 (1428725461874114561)]} 0 3
[junit4:junit4] 2> 11837 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10001 (1428725461874114560)]} 0 3
[junit4:junit4] 2> 11854 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10002 (1428725461895086080)]} 0 0
[junit4:junit4] 2> 11855 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[2 (1428725461895086081)]} 0 1
[junit4:junit4] 2> 11857 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10002 (1428725461897183232)]} 0 1
[junit4:junit4] 2> 11857 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[2 (1428725461897183233)]} 0 1
[junit4:junit4] 2> 11946 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[3 (1428725461991555073)]} 0 0
[junit4:junit4] 2> 11946 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10003 (1428725461991555072)]} 0 0
[junit4:junit4] 2> 11949 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[3 (1428725461993652224)]} 0 1
[junit4:junit4] 2> 11949 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10003 (1428725461993652225)]} 0 1
[junit4:junit4] 2> 11976 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10004 (1428725462021963777)]} 0 1
[junit4:junit4] 2> 11976 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[4 (1428725462021963776)]} 0 1
[junit4:junit4] 2> 11978 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10004 (1428725462025109505)]} 0 0
[junit4:junit4] 2> 11978 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[4 (1428725462025109504)]} 0 0
[junit4:junit4] 2> 12032 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[3 (-1428725462081732608)]} 0 0
[junit4:junit4] 2> 12032 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10003 (-1428725462081732609)]} 0 0
[junit4:junit4] 2> 12035 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[3 (-1428725462083829760)]} 0 1
[junit4:junit4] 2> 12035 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10003 (-1428725462083829761)]} 0 1
[junit4:junit4] 2> 12037 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10005 (1428725462085926913)]} 0 1
[junit4:junit4] 2> 12037 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[5 (1428725462085926912)]} 0 1
[junit4:junit4] 2> 12039 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10005 (1428725462089072640)]} 0 0
[junit4:junit4] 2> 12039 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[5 (1428725462089072641)]} 0 0
[junit4:junit4] 2> 12086 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[6 (1428725462137307137)]} 0 1
[junit4:junit4] 2> 12086 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10006 (1428725462137307136)]} 0 1
[junit4:junit4] 2> 12088 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10006 (1428725462140452864)]} 0 0
[junit4:junit4] 2> 12088 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[6 (1428725462140452865)]} 0 0
[junit4:junit4] 2> 12130 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10007 (1428725462184493056)]} 0 0
[junit4:junit4] 2> 12130 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[7 (1428725462184493057)]} 0 0
[junit4:junit4] 2> 12132 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10007 (1428725462186590208)]} 0 0
[junit4:junit4] 2> 12132 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[7 (1428725462186590209)]} 0 0
[junit4:junit4] 2> 12217 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[6 (-1428725462275719168)]} 0 1
[junit4:junit4] 2> 12217 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10006 (-1428725462274670592)]} 0 1
[junit4:junit4] 2> 12219 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[10006 (-1428725462277816321)]} 0 0
[junit4:junit4] 2> 12219 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[6 (-1428725462277816320)]} 0 0
[junit4:junit4] 2> 12221 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[8 (1428725462278864896)]} 0 1
[junit4:junit4] 2> 12221 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10008 (1428725462278864897)]} 0 1
[junit4:junit4] 2> 12223 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[8 (1428725462282010624)]} 0 0
[junit4:junit4] 2> 12223 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10008 (1428725462282010625)]} 0 0
[junit4:junit4] 2> 12238 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[9 (1428725462297739264)]} 0 0
[junit4:junit4] 2> 12238 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10009 (1428725462297739265)]} 0 0
[junit4:junit4] 2> 12240 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[9 (1428725462299836416)]} 0 0
[junit4:junit4] 2> 12240 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10009 (1428725462299836417)]} 0 0
[junit4:junit4] 2> 12254 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[8 (-1428725462314516480)]} 0 0
[junit4:junit4] 2> 12254 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10008 (-1428725462314516481)]} 0 0
[junit4:junit4] 2> 12256 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[8 (-1428725462316613632)]} 0 0
[junit4:junit4] 2> 12256 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10008 (-1428725462316613633)]} 0 0
[junit4:junit4] 2> 12258 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10 (1428725462318710784)]} 0 0
[junit4:junit4] 2> 12258 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10010 (1428725462318710785)]} 0 0
[junit4:junit4] 2> 12260 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10 (1428725462320807936)]} 0 0
[junit4:junit4] 2> 12261 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10010 (1428725462320807937)]} 0 1
[junit4:junit4] 2> 12344 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[9 (-1428725462408888320)]} 0 0
[junit4:junit4] 2> 12345 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10009 (-1428725462408888321)]} 0 1
[junit4:junit4] 2> 12346 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[9 (-1428725462410985472)]} 0 0
[junit4:junit4] 2> 12346 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10009 (-1428725462410985473)]} 0 0
[junit4:junit4] 2> 12348 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[11 (1428725462413082624)]} 0 0
[junit4:junit4] 2> 12348 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10011 (1428725462413082625)]} 0 0
[junit4:junit4] 2> 12351 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[11 (1428725462415179776)]} 0 1
[junit4:junit4] 2> 12351 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10011 (1428725462415179777)]} 0 1
[junit4:junit4] 2> 12442 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[10 (-1428725462510600192)]} 0 1
[junit4:junit4] 2> 12442 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10010 (-1428725462511648768)]} 0 0
[junit4:junit4] 2> 12444 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10 (-1428725462513745920)]} 0 0
[junit4:junit4] 2> 12444 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[10010 (-1428725462513745921)]} 0 0
[junit4:junit4] 2> 12446 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[12 (1428725462515843072)]} 0 0
[junit4:junit4] 2> 12446 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10012 (1428725462515843073)]} 0 0
[junit4:junit4] 2> 12448 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[12 (1428725462517940224)]} 0 0
[junit4:junit4] 2> 12449 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10012 (1428725462517940225)]} 0 1
[junit4:junit4] 2> 12500 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[13 (1428725462571417600)]} 0 1
[junit4:junit4] 2> 12500 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10013 (1428725462572466176)]} 0 0
[junit4:junit4] 2> 12502 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[13 (1428725462574563328)]} 0 0
[junit4:junit4] 2> 12503 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10013 (1428725462574563329)]} 0 1
[junit4:junit4] 2> 12543 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[11 (-1428725462617554944)]} 0 0
[junit4:junit4] 2> 12544 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10011 (-1428725462618603520)]} 0 0
[junit4:junit4] 2> 12545 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[11 (-1428725462619652096)]} 0 0
[junit4:junit4] 2> 12546 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10011 (-1428725462619652097)]} 0 1
[junit4:junit4] 2> 12547 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[14 (1428725462621749248)]} 0 0
[junit4:junit4] 2> 12548 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10014 (1428725462621749249)]} 0 1
[junit4:junit4] 2> 12549 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[14 (1428725462623846400)]} 0 0
[junit4:junit4] 2> 12550 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10014 (1428725462623846401)]} 0 1
[junit4:junit4] 2> 12584 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[13 (-1428725462660546560)]} 0 0
[junit4:junit4] 2> 12585 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10013 (-1428725462661595136)]} 0 0
[junit4:junit4] 2> 12586 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[13 (-1428725462662643712)]} 0 0
[junit4:junit4] 2> 12587 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[10013 (-1428725462663692288)]} 0 1
[junit4:junit4] 2> 12589 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[15 (1428725462664740864)]} 0 1
[junit4:junit4] 2> 12589 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10015 (1428725462664740865)]} 0 1
[junit4:junit4] 2> 12591 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[15 (1428725462666838016)]} 0 1
[junit4:junit4] 2> 12591 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10015 (1428725462667886592)]} 0 0
[junit4:junit4] 2> 12690 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[16 (1428725462771695617)]} 0 0
[junit4:junit4] 2> 12691 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10016 (1428725462771695616)]} 0 1
[junit4:junit4] 2> 12693 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[16 (1428725462773792768)]} 0 1
[junit4:junit4] 2> 12693 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10016 (1428725462774841344)]} 0 0
[junit4:junit4] 2> 12701 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[17 (1428725462783229952)]} 0 0
[junit4:junit4] 2> 12701 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10017 (1428725462783229953)]} 0 0
[junit4:junit4] 2> 12703 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[17 (1428725462785327104)]} 0 0
[junit4:junit4] 2> 12703 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10017 (1428725462785327105)]} 0 0
[junit4:junit4] 2> 12767 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12767 T2923 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:46739_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46739/u"}
[junit4:junit4] 2> 12770 T2942 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> 12770 T2958 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> 12770 T2922 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> 12770 T2929 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> 12775 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[17 (-1428725462860824576)]} 0 0
[junit4:junit4] 2> 12775 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10017 (-1428725462860824577)]} 0 0
[junit4:junit4] 2> C445_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:46739_u, base_url=http://127.0.0.1:46739/u}
[junit4:junit4] 2> 12782 T2952 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 12783 T2952 C445 P46739 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20660e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1578229),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12783 T2952 C445 P46739 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12784 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10017 (-1428725462862921729)]} 0 2
[junit4:junit4] 2> 12784 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[17 (-1428725462862921728)]} 0 2
[junit4:junit4] 2> 12784 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10017 (-1428725462862921729)]} 0 7
[junit4:junit4] 2> 12784 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[17 (-1428725462862921728)]} 0 7
[junit4:junit4] 2> 12786 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10018 (1428725462872358912)]} 0 0
[junit4:junit4] 2> 12786 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[18 (1428725462872358913)]} 0 0
[junit4:junit4] 2> 12791 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1428725462874456064)]} 0 1
[junit4:junit4] 2> 12791 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1428725462874456065)]} 0 1
[junit4:junit4] 2> 12791 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[18 (1428725462874456064)]} 0 3
[junit4:junit4] 2> 12792 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10018 (1428725462874456065)]} 0 4
[junit4:junit4] 2> 12862 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[18 (-1428725462952050688)]} 0 0
[junit4:junit4] 2> 12862 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10018 (-1428725462952050689)]} 0 0
[junit4:junit4] 2> 12866 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[18 (-1428725462954147841)]} 0 0
[junit4:junit4] 2> 12866 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10018 (-1428725462954147840)]} 0 0
[junit4:junit4] 2> 12866 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[18 (-1428725462954147841)]} 0 2
[junit4:junit4] 2> 12866 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[10018 (-1428725462954147840)]} 0 2
[junit4:junit4] 2> 12868 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[19 (1428725462958342144)]} 0 0
[junit4:junit4] 2> 12868 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10019 (1428725462958342145)]} 0 0
[junit4:junit4] 2> 12872 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1428725462960439296)]} 0 0
[junit4:junit4] 2> 12873 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1428725462960439297)]} 0 1
[junit4:junit4] 2> 12873 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[19 (1428725462960439296)]} 0 3
[junit4:junit4] 2> 12873 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10019 (1428725462960439297)]} 0 3
[junit4:junit4] 2> 12921 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[20 (1428725463012868097)]} 0 1
[junit4:junit4] 2> 12921 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10020 (1428725463012868096)]} 0 1
[junit4:junit4] 2> 12925 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1428725463016013824)]} 0 1
[junit4:junit4] 2> 12925 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[20 (1428725463016013824)]} 0 2
[junit4:junit4] 2> 12925 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1428725463016013825)]} 0 0
[junit4:junit4] 2> 12926 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10020 (1428725463016013825)]} 0 3
[junit4:junit4] 2> 12945 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[19 (-1428725463039082496)]} 0 0
[junit4:junit4] 2> 12946 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10019 (-1428725463040131072)]} 0 0
[junit4:junit4] 2> 12949 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[19 (-1428725463041179648)]} 0 0
[junit4:junit4] 2> 12949 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[19 (-1428725463041179648)]} 0 2
[junit4:junit4] 2> 12949 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10019 (-1428725463041179649)]} 0 0
[junit4:junit4] 2> 12950 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10019 (-1428725463041179649)]} 0 3
[junit4:junit4] 2> 12951 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[21 (1428725463045373952)]} 0 0
[junit4:junit4] 2> 12952 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10021 (1428725463046422528)]} 0 0
[junit4:junit4] 2> 12955 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1428725463047471104)]} 0 0
[junit4:junit4] 2> 12956 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1428725463048519680)]} 0 1
[junit4:junit4] 2> 12956 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[21 (1428725463047471104)]} 0 3
[junit4:junit4] 2> 12956 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10021 (1428725463048519680)]} 0 2
[junit4:junit4] 2> 13019 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[22 (1428725463115628544)]} 0 1
[junit4:junit4] 2> 13019 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10022 (1428725463115628545)]} 0 1
[junit4:junit4] 2> 13023 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1428725463118774272)]} 0 0
[junit4:junit4] 2> 13024 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1428725463118774273)]} 0 1
[junit4:junit4] 2> 13024 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[22 (1428725463118774272)]} 0 3
[junit4:junit4] 2> 13024 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10022 (1428725463118774273)]} 0 3
[junit4:junit4] 2> 13105 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10022 (-1428725463205806080)]} 0 1
[junit4:junit4] 2> 13105 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[22 (-1428725463205806081)]} 0 1
[junit4:junit4] 2> 13109 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10022 (-1428725463208951808)]} 0 0
[junit4:junit4] 2> 13109 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[22 (-1428725463208951809)]} 0 0
[junit4:junit4] 2> 13110 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[10022 (-1428725463208951808)]} 0 3
[junit4:junit4] 2> 13110 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[22 (-1428725463208951809)]} 0 3
[junit4:junit4] 2> 13113 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10023 (1428725463214194688)]} 0 1
[junit4:junit4] 2> 13114 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[23 (1428725463215243264)]} 0 1
[junit4:junit4] 2> 13118 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1428725463218388992)]} 0 0
[junit4:junit4] 2> 13118 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1428725463218388993)]} 0 0
[junit4:junit4] 2> 13119 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10023 (1428725463218388992)]} 0 3
[junit4:junit4] 2> 13119 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[23 (1428725463218388993)]} 0 3
[junit4:junit4] 2> 13139 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10024 (1428725463241457664)]} 0 1
[junit4:junit4] 2> 13139 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[24 (1428725463242506240)]} 0 0
[junit4:junit4] 2> 13143 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1428725463244603392)]} 0 1
[junit4:junit4] 2> 13143 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1428725463244603393)]} 0 0
[junit4:junit4] 2> 13143 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10024 (1428725463244603392)]} 0 2
[junit4:junit4] 2> 13144 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[24 (1428725463244603393)]} 0 3
[junit4:junit4] 2> 13207 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[24 (-1428725463313809409)]} 0 0
[junit4:junit4] 2> 13207 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10024 (-1428725463313809408)]} 0 0
[junit4:junit4] 2> 13211 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10024 (-1428725463315906560)]} 0 1
[junit4:junit4] 2> 13211 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[24 (-1428725463315906561)]} 0 0
[junit4:junit4] 2> 13211 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10024 (-1428725463315906560)]} 0 2
[junit4:junit4] 2> 13211 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[24 (-1428725463315906561)]} 0 2
[junit4:junit4] 2> 13213 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10025 (1428725463320100864)]} 0 0
[junit4:junit4] 2> 13214 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[25 (1428725463320100865)]} 0 1
[junit4:junit4] 2> 13217 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1428725463322198016)]} 0 0
[junit4:junit4] 2> 13218 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10025 (1428725463322198016)]} 0 3
[junit4:junit4] 2> 13218 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1428725463322198017)]} 0 1
[junit4:junit4] 2> 13219 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[25 (1428725463322198017)]} 0 4
[junit4:junit4] 2> 13284 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10026 (1428725463394549760)]} 0 0
[junit4:junit4] 2> 13285 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[26 (1428725463394549761)]} 0 1
[junit4:junit4] 2> 13289 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1428725463396646912)]} 0 1
[junit4:junit4] 2> 13289 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10026 (1428725463396646912)]} 0 3
[junit4:junit4] 2> 13289 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1428725463396646913)]} 0 0
[junit4:junit4] 2> 13290 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[26 (1428725463396646913)]} 0 4
[junit4:junit4] 2> 13365 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10027 (1428725463478435840)]} 0 1
[junit4:junit4] 2> 13365 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[27 (1428725463479484416)]} 0 0
[junit4:junit4] 2> 13370 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1428725463481581568)]} 0 1
[junit4:junit4] 2> 13371 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1428725463482630144)]} 0 1
[junit4:junit4] 2> 13371 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10027 (1428725463481581568)]} 0 4
[junit4:junit4] 2> 13372 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[27 (1428725463482630144)]} 0 4
[junit4:junit4] 2> 13457 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[28 (1428725463574904833)]} 0 1
[junit4:junit4] 2> 13457 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10028 (1428725463574904832)]} 0 1
[junit4:junit4] 2> 13462 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1428725463579099136)]} 0 0
[junit4:junit4] 2> 13463 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10028 (1428725463579099136)]} 0 3
[junit4:junit4] 2> 13463 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1428725463579099137)]} 0 1
[junit4:junit4] 2> 13464 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[28 (1428725463579099137)]} 0 3
[junit4:junit4] 2> 13551 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10029 (1428725463674519552)]} 0 0
[junit4:junit4] 2> 13552 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[29 (1428725463674519553)]} 0 1
[junit4:junit4] 2> 13555 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1428725463676616704)]} 0 0
[junit4:junit4] 2> 13556 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10029 (1428725463676616704)]} 0 3
[junit4:junit4] 2> 13556 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1428725463677665280)]} 0 0
[junit4:junit4] 2> 13557 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[29 (1428725463677665280)]} 0 3
[junit4:junit4] 2> 13639 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10030 (1428725463765745664)]} 0 1
[junit4:junit4] 2> 13639 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[30 (1428725463766794240)]} 0 0
[junit4:junit4] 2> 13643 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1428725463768891392)]} 0 0
[junit4:junit4] 2> 13643 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1428725463768891393)]} 0 0
[junit4:junit4] 2> 13643 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10030 (1428725463768891392)]} 0 2
[junit4:junit4] 2> 13644 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[30 (1428725463768891393)]} 0 3
[junit4:junit4] 2> 13700 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10031 (1428725463829708801)]} 0 1
[junit4:junit4] 2> 13700 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[31 (1428725463829708800)]} 0 1
[junit4:junit4] 2> 13704 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1428725463832854528)]} 0 1
[junit4:junit4] 2> 13704 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10031 (1428725463832854528)]} 0 2
[junit4:junit4] 2> 13705 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1428725463832854529)]} 0 1
[junit4:junit4] 2> 13705 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[31 (1428725463832854529)]} 0 3
[junit4:junit4] 2> 13742 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10026 (-1428725463874797568)]} 0 1
[junit4:junit4] 2> 13742 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[26 (-1428725463874797569)]} 0 0
[junit4:junit4] 2> 13745 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10026 (-1428725463876894720)]} 0 0
[junit4:junit4] 2> 13746 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[26 (-1428725463876894721)]} 0 1
[junit4:junit4] 2> 13746 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10026 (-1428725463876894720)]} 0 2
[junit4:junit4] 2> 13746 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[26 (-1428725463876894721)]} 0 2
[junit4:junit4] 2> 13748 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10032 (1428725463881089024)]} 0 0
[junit4:junit4] 2> 13748 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[32 (1428725463881089025)]} 0 0
[junit4:junit4] 2> 13752 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10032 (1428725463883186176)]} 0 1
[junit4:junit4] 2> 13752 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10032 (1428725463883186176)]} 0 2
[junit4:junit4] 2> 13752 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1428725463883186177)]} 0 0
[junit4:junit4] 2> 13753 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[32 (1428725463883186177)]} 0 3
[junit4:junit4] 2> 13819 T2900 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 46739
[junit4:junit4] 2> 13819 T2900 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=12303834
[junit4:junit4] 2> 13833 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10033 (1428725463969169408)]} 0 1
[junit4:junit4] 2> 13833 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[33 (1428725463970217984)]} 0 0
[junit4:junit4] 2> 13837 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10033 (1428725463972315136)]} 0 0
[junit4:junit4] 2> 13838 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1428725463972315137)]} 0 1
[junit4:junit4] 2> 13838 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10033 (1428725463972315136)]} 0 3
[junit4:junit4] 2> 13838 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[33 (1428725463972315137)]} 0 3
[junit4:junit4] 2> 13899 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10030 (-1428725464039424000)]} 0 0
[junit4:junit4] 2> 13899 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[30 (-1428725464039424001)]} 0 0
[junit4:junit4] 2> 13903 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[30 (-1428725464042569729)]} 0 0
[junit4:junit4] 2> 13903 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10030 (-1428725464042569728)]} 0 0
[junit4:junit4] 2> 13904 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[30 (-1428725464042569729)]} 0 3
[junit4:junit4] 2> 13904 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[10030 (-1428725464042569728)]} 0 3
[junit4:junit4] 2> 13915 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[34 (1428725464055152640)]} 0 1
[junit4:junit4] 2> 13915 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10034 (1428725464056201216)]} 0 0
[junit4:junit4] 2> 13919 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1428725464058298368)]} 0 1
[junit4:junit4] 2> 13919 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[34 (1428725464058298368)]} 0 3
[junit4:junit4] 2> 13919 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10034 (1428725464058298369)]} 0 0
[junit4:junit4] 2> 13920 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10034 (1428725464058298369)]} 0 3
[junit4:junit4] 2> 13992 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[35 (1428725464136941568)]} 0 1
[junit4:junit4] 2> 13993 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10035 (1428725464136941569)]} 0 1
[junit4:junit4] 2> 13998 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1428725464140087296)]} 0 0
[junit4:junit4] 2> 13999 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10035 (1428725464140087297)]} 0 1
[junit4:junit4] 2> 13999 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[35 (1428725464140087296)]} 0 4
[junit4:junit4] 2> 14000 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10035 (1428725464140087297)]} 0 5
[junit4:junit4] 2> 14095 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[32 (-1428725464244944896)]} 0 0
[junit4:junit4] 2> 14096 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[10032 (-1428725464245993472)]} 0 0
[junit4:junit4] 2> 14100 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10032 (-1428725464249139200)]} 0 0
[junit4:junit4] 2> 14100 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[32 (-1428725464248090624)]} 0 0
[junit4:junit4] 2> 14101 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10032 (-1428725464249139200)]} 0 3
[junit4:junit4] 2> 14101 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[32 (-1428725464248090624)]} 0 3
[junit4:junit4] 2> 14105 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[36 (1428725464254382080)]} 0 1
[junit4:junit4] 2> 14106 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10036 (1428725464254382081)]} 0 2
[junit4:junit4] 2> 14111 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1428725464258576384)]} 0 1
[junit4:junit4] 2> 14111 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[36 (1428725464258576384)]} 0 3
[junit4:junit4] 2> 14111 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10036 (1428725464258576385)]} 0 0
[junit4:junit4] 2> 14113 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10036 (1428725464258576385)]} 0 5
[junit4:junit4] 2> 14197 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[37 (1428725464351899648)]} 0 0
[junit4:junit4] 2> 14198 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10037 (1428725464352948224)]} 0 0
[junit4:junit4] 2> 14201 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1428725464353996800)]} 0 0
[junit4:junit4] 2> 14202 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[37 (1428725464353996800)]} 0 3
[junit4:junit4] 2> 14202 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10037 (1428725464355045376)]} 0 0
[junit4:junit4] 2> 14203 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10037 (1428725464355045376)]} 0 3
[junit4:junit4] 2> 14260 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[38 (1428725464416911360)]} 0 1
[junit4:junit4] 2> 14260 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10038 (1428725464417959936)]} 0 0
[junit4:junit4] 2> 14264 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1428725464420057088)]} 0 0
[junit4:junit4] 2> 14265 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[38 (1428725464420057088)]} 0 3
[junit4:junit4] 2> 14265 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10038 (1428725464420057089)]} 0 1
[junit4:junit4] 2> 14266 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10038 (1428725464420057089)]} 0 4
[junit4:junit4] 2> 14273 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14273 T2923 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46739_u_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:46739_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46739/u"}
[junit4:junit4] 2> 14277 T2942 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> 14277 T2958 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> 14277 T2922 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> 14277 T2929 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> 14308 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[37 (-1428725464468291584)]} 0 0
[junit4:junit4] 2> 14309 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10037 (-1428725464469340160)]} 0 1
[junit4:junit4] 2> 14310 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[37 (-1428725464470388736)]} 0 0
[junit4:junit4] 2> 14310 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10037 (-1428725464470388737)]} 0 0
[junit4:junit4] 2> 14312 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[39 (1428725464472485888)]} 0 0
[junit4:junit4] 2> 14313 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10039 (1428725464472485889)]} 0 1
[junit4:junit4] 2> 14315 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[39 (1428725464474583040)]} 0 1
[junit4:junit4] 2> 14315 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10039 (1428725464475631616)]} 0 0
[junit4:junit4] 2> 14374 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[39 (-1428725464537497600)]} 0 0
[junit4:junit4] 2> 14374 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10039 (-1428725464537497601)]} 0 0
[junit4:junit4] 2> 14376 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[39 (-1428725464539594752)]} 0 0
[junit4:junit4] 2> 14376 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10039 (-1428725464539594753)]} 0 0
[junit4:junit4] 2> 14378 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[40 (1428725464541691904)]} 0 0
[junit4:junit4] 2> 14379 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10040 (1428725464541691905)]} 0 1
[junit4:junit4] 2> 14381 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[40 (1428725464543789056)]} 0 1
[junit4:junit4] 2> 14381 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10040 (1428725464543789057)]} 0 1
[junit4:junit4] 2> 14440 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[41 (1428725464606703616)]} 0 0
[junit4:junit4] 2> 14440 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10041 (1428725464606703617)]} 0 0
[junit4:junit4] 2> 14442 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[41 (1428725464608800768)]} 0 0
[junit4:junit4] 2> 14443 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10041 (1428725464608800769)]} 0 1
[junit4:junit4] 2> 14449 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[42 (1428725464616140800)]} 0 0
[junit4:junit4] 2> 14449 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10042 (1428725464616140801)]} 0 0
[junit4:junit4] 2> 14451 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[42 (1428725464618237952)]} 0 0
[junit4:junit4] 2> 14452 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10042 (1428725464618237953)]} 0 1
[junit4:junit4] 2> 14536 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[41 (-1428725464707366912)]} 0 0
[junit4:junit4] 2> 14537 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10041 (-1428725464708415488)]} 0 0
[junit4:junit4] 2> 14538 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[41 (-1428725464709464064)]} 0 0
[junit4:junit4] 2> 14539 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10041 (-1428725464710512640)]} 0 0
[junit4:junit4] 2> 14541 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10043 (1428725464711561217)]} 0 1
[junit4:junit4] 2> 14541 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[43 (1428725464711561216)]} 0 1
[junit4:junit4] 2> 14543 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10043 (1428725464714706944)]} 0 0
[junit4:junit4] 2> 14543 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[43 (1428725464714706945)]} 0 0
[junit4:junit4] 2> 14582 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10044 (1428725464754552832)]} 0 1
[junit4:junit4] 2> 14582 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[44 (1428725464754552833)]} 0 1
[junit4:junit4] 2> 14585 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10044 (1428725464757698560)]} 0 1
[junit4:junit4] 2> 14585 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[44 (1428725464758747136)]} 0 0
[junit4:junit4] 2> 14623 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10045 (1428725464797544448)]} 0 1
[junit4:junit4] 2> 14624 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[45 (1428725464798593024)]} 0 1
[junit4:junit4] 2> 14626 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10045 (1428725464801738752)]} 0 1
[junit4:junit4] 2> 14627 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[45 (1428725464801738753)]} 0 1
[junit4:junit4] 2> 14704 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10046 (1428725464883527680)]} 0 0
[junit4:junit4] 2> 14705 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[46 (1428725464884576256)]} 0 0
[junit4:junit4] 2> 14706 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10046 (1428725464885624832)]} 0 0
[junit4:junit4] 2> 14707 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[46 (1428725464886673408)]} 0 0
[junit4:junit4] 2> 14746 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10043 (-1428725464927567872)]} 0 0
[junit4:junit4] 2> 14747 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[43 (-1428725464928616448)]} 0 0
[junit4:junit4] 2> 14748 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10043 (-1428725464929665024)]} 0 0
[junit4:junit4] 2> 14749 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[43 (-1428725464930713600)]} 0 0
[junit4:junit4] 2> 14750 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10047 (1428725464931762176)]} 0 0
[junit4:junit4] 2> 14751 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[47 (1428725464932810752)]} 0 0
[junit4:junit4] 2> 14752 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10047 (1428725464933859328)]} 0 0
[junit4:junit4] 2> 14753 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[47 (1428725464934907904)]} 0 0
[junit4:junit4] 2> 14799 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10048 (1428725464982093824)]} 0 1
[junit4:junit4] 2> 14799 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[48 (1428725464983142400)]} 0 0
[junit4:junit4] 2> 14801 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10048 (1428725464985239552)]} 0 0
[junit4:junit4] 2> 14801 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[48 (1428725464985239553)]} 0 0
[junit4:junit4] 2> C445_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46739_u, base_url=http://127.0.0.1:46739/u}
[junit4:junit4] 2> 14824 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59746/u/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 14825 T2961 C445 P46739 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46739/u START replicas=[http://127.0.0.1:59746/u/collection1/] nUpdates=100
[junit4:junit4] 2> 14825 T2961 C445 P46739 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 14826 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 14827 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 14827 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 14827 T2961 C445 P46739 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/tlog/tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 14827 T2936 C447 P59746 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 14828 T2961 C445 P46739 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59746/u/collection1/. core=collection1
[junit4:junit4] 2> 14828 T2961 C445 P46739 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14834 T2938 C447 P59746 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14836 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[10044 (-1428725465021939712)]} 0 0
[junit4:junit4] 2> 14837 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[44 (-1428725465021939713)]} 0 1
[junit4:junit4] 2> 14839 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10044 (-1428725465025085440)]} 0 0
[junit4:junit4] 2> 14839 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[44 (-1428725465025085441)]} 0 0
[junit4:junit4] 2> 14842 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10049 (1428725465027182592)]} 0 1
[junit4:junit4] 2> 14842 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[49 (1428725465027182593)]} 0 1
[junit4:junit4] 2> 14842 T2938 C447 P59746 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12c961d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1962ee1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12c961d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1962ee1),segFN=segments_2,generation=2,filenames=[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.tip, _1.cbnd, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.dvdm, _1.si, _0.tim, segments_2, _0.fdx, _0.tip, _0.fdt]
[junit4:junit4] 2> 14843 T2938 C447 P59746 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.tip, _1.cbnd, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.dvdm, _1.si, _0.tim, segments_2, _0.fdx, _0.tip, _0.fdt]
[junit4:junit4] 2> 14843 T2938 C447 P59746 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1
[junit4:junit4] 2> 14844 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10049 (1428725465029279744)]} 0 1
[junit4:junit4] 2> 14844 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[49 (1428725465029279745)]} 0 1
[junit4:junit4] 2> 14844 T2938 C447 P59746 oass.SolrIndexSearcher.<init> Opening Searcher@1820d2b realtime
[junit4:junit4] 2> 14845 T2938 C447 P59746 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 14845 T2938 C447 P59746 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 14846 T2961 C445 P46739 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14846 T2961 C445 P46739 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 14847 T2935 C447 P59746 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14848 T2935 C447 P59746 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 14848 T2961 C445 P46739 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 14848 T2961 C445 P46739 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 14848 T2961 C445 P46739 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 14850 T2936 C447 P59746 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1
[junit4:junit4] 2> 14850 T2936 C447 P59746 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty1/index
[junit4:junit4] 2> 14851 T2936 C447 P59746 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 14851 T2961 C445 P46739 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 27
[junit4:junit4] 2> 14852 T2961 C445 P46739 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202 forceNew:false
[junit4:junit4] 2> 14852 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 14852 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10045 (-1428725465038716928)]} 0 0
[junit4:junit4] 2> 14852 T2961 C445 P46739 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79) fullCopy=true
[junit4:junit4] 2> 14852 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[45 (-1428725465038716929)]} 0 0
[junit4:junit4] 2> 14854 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10045 (-1428725465040814080)]} 0 0
[junit4:junit4] 2> 14854 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[45 (-1428725465040814081)]} 0 0
[junit4:junit4] 2> 14854 T2935 C447 P59746 REQ /replication {file=_1.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14856 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10050 (1428725465041862656)]} 0 1
[junit4:junit4] 2> 14856 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[50 (1428725465042911232)]} 0 0
[junit4:junit4] 2> 14856 T2936 C447 P59746 REQ /replication {file=_0.cbnd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14858 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10050 (1428725465045008384)]} 0 0
[junit4:junit4] 2> 14858 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[50 (1428725465045008385)]} 0 0
[junit4:junit4] 2> 14859 T2935 C447 P59746 REQ /replication {file=_0.dvdm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14861 T2936 C447 P59746 REQ /replication {file=_0.cbnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14864 T2938 C447 P59746 REQ /replication {file=_1.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14868 T2937 C447 P59746 REQ /replication {file=_1.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14871 T2935 C447 P59746 REQ /replication {file=_1.cbnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14875 T2936 C447 P59746 REQ /replication {file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14878 T2938 C447 P59746 REQ /replication {file=_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14882 T2937 C447 P59746 REQ /replication {file=_1.cbnd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14885 T2935 C447 P59746 REQ /replication {file=_1.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14889 T2936 C447 P59746 REQ /replication {file=_0.dvdd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14892 T2938 C447 P59746 REQ /replication {file=_1.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14895 T2937 C447 P59746 REQ /replication {file=_0.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14940 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10051 (1428725465129943040)]} 0 1
[junit4:junit4] 2> 14940 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[51 (1428725465129943041)]} 0 1
[junit4:junit4] 2> 14943 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10051 (1428725465133088768)]} 0 1
[junit4:junit4] 2> 14943 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[51 (1428725465134137344)]} 0 1
[junit4:junit4] 2> 14949 T2938 C447 P59746 REQ /replication {file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14962 T2935 C447 P59746 REQ /replication {file=_1_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14964 T2936 C447 P59746 REQ /replication {file=_1.dvdd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14967 T2937 C447 P59746 REQ /replication {file=_1.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14970 T2938 C447 P59746 REQ /replication {file=_1.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14972 T2935 C447 P59746 REQ /replication {file=_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14974 T2936 C447 P59746 REQ /replication {file=_1.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14977 T2937 C447 P59746 REQ /replication {file=_1.dvdm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14979 T2938 C447 P59746 REQ /replication {file=_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14979 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10052 (1428725465171886080)]} 0 1
[junit4:junit4] 2> 14979 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[52 (1428725465171886081)]} 0 0
[junit4:junit4] 2> 14981 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10052 (1428725465173983232)]} 0 0
[junit4:junit4] 2> 14981 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[52 (1428725465173983233)]} 0 0
[junit4:junit4] 2> 14982 T2937 C447 P59746 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14984 T2938 C447 P59746 REQ /replication {file=_0.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14986 T2935 C447 P59746 REQ /replication {file=_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14988 T2936 C447 P59746 REQ /replication {file=_0.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14989 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 14989 T2961 C445 P46739 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 14990 T2961 C445 P46739 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130306025941202
[junit4:junit4] 2> 14990 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 14990 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 14991 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 14991 T2961 C445 P46739 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 14991 T2961 C445 P46739 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 14991 T2961 C445 P46739 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 14992 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 14992 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 14992 T2961 C445 P46739 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index/ new=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 14993 T2961 C445 P46739 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79),segFN=segments_2,generation=2,filenames=[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, segments_2, _0.fdx, _0.tip, _0.fdt]
[junit4:junit4] 2> 14993 T2961 C445 P46739 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, segments_2, _0.fdx, _0.tip, _0.fdt]
[junit4:junit4] 2> 14994 T2961 C445 P46739 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 14994 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 14995 T2961 C445 P46739 oass.SolrIndexSearcher.<init> Opening Searcher@1e4ad77 main
[junit4:junit4] 2> 14996 T2960 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e4ad77 main{StandardDirectoryReader(segments_2:5:nrt _0(5.0):C71/28 _1(5.0):C25/10)}
[junit4:junit4] 2> 14996 T2960 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 14996 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 14996 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 14997 T2961 C445 P46739 oasc.CachingDirectoryFactory.close Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 14997 T2961 C445 P46739 oash.SnapPuller$2.preClose removing old index files MockDirWrapper(org.apache.lucene.store.RAMDirectory@20660e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1578229)
[junit4:junit4] 2> 14997 T2961 C445 P46739 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index
[junit4:junit4] 2> 14997 T2961 C445 P46739 oash.SnapPuller$2.postClose removing old index directory MockDirWrapper(org.apache.lucene.store.RAMDirectory@20660e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1578229)
[junit4:junit4] 2> 14998 T2961 C445 P46739 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 14998 T2969 C445 P46739 oasu.UpdateLog$LogReplayer.doReplay WARNING Starting log replay tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/tlog/tlog.0000000000000000000 refcount=2} active=true starting pos=6002
[junit4:junit4] 2> 14998 T2969 C445 P46739 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14999 T2969 C445 P46739 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79),segFN=segments_2,generation=2,filenames=[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, segments_2, _0.fdx, _0.tip, _0.fdt]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79),segFN=segments_3,generation=3,filenames=[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, _0.fdx, _0.tip, segments_3, _0.fdt]
[junit4:junit4] 2> 14999 T2969 C445 P46739 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, _0.fdx, _0.tip, segments_3, _0.fdt]
[junit4:junit4] 2> 14999 T2969 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 15000 T2969 C445 P46739 oass.SolrIndexSearcher.<init> Opening Searcher@876c09 main
[junit4:junit4] 2> 15000 T2969 C445 P46739 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15001 T2960 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@876c09 main{StandardDirectoryReader(segments_2:5:nrt _0(5.0):C71/28 _1(5.0):C25/10)}
[junit4:junit4] 2> 15001 T2960 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 15001 T2969 C445 P46739 oasu.UpdateLog$LogReplayer.run WARNING Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=6002}
[junit4:junit4] 2> 15001 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15001 T2961 C445 P46739 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15002 T2961 C445 P46739 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15002 T2961 C445 P46739 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15037 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[46 (-1428725465232703488)]} 0 0
[junit4:junit4] 2> 15037 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10046 (-1428725465232703489)]} 0 0
[junit4:junit4] 2> 15039 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[46 (-1428725465234800640)]} 0 0
[junit4:junit4] 2> 15040 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10046 (-1428725465235849216)]} 0 0
[junit4:junit4] 2> 15042 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[53 (1428725465236897792)]} 0 1
[junit4:junit4] 2> 15042 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10053 (1428725465236897793)]} 0 1
[junit4:junit4] 2> 15044 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[53 (1428725465238994944)]} 0 1
[junit4:junit4] 2> 15044 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10053 (1428725465240043520)]} 0 0
[junit4:junit4] 2> 15072 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[47 (-1428725465269403648)]} 0 1
[junit4:junit4] 2> 15072 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10047 (-1428725465269403649)]} 0 0
[junit4:junit4] 2> 15074 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[47 (-1428725465271500800)]} 0 0
[junit4:junit4] 2> 15074 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10047 (-1428725465271500801)]} 0 0
[junit4:junit4] 2> 15076 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[54 (1428725465272549376)]} 0 1
[junit4:junit4] 2> 15076 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10054 (1428725465273597952)]} 0 0
[junit4:junit4] 2> 15078 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[54 (1428725465274646528)]} 0 1
[junit4:junit4] 2> 15078 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10054 (1428725465275695104)]} 0 0
[junit4:junit4] 2> 15142 T2917 C446 P60402 /update {wt=javabin&version=2} {delete=[51 (-1428725465342803968)]} 0 0
[junit4:junit4] 2> 15142 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10051 (-1428725465342803969)]} 0 0
[junit4:junit4] 2> 15144 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[51 (-1428725465344901120)]} 0 0
[junit4:junit4] 2> 15144 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10051 (-1428725465344901121)]} 0 0
[junit4:junit4] 2> 15146 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[55 (1428725465346998272)]} 0 0
[junit4:junit4] 2> 15146 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10055 (1428725465346998273)]} 0 0
[junit4:junit4] 2> 15149 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[55 (1428725465349095424)]} 0 1
[junit4:junit4] 2> 15149 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10055 (1428725465349095425)]} 0 1
[junit4:junit4] 2> 15217 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10056 (1428725465421447169)]} 0 0
[junit4:junit4] 2> 15218 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[56 (1428725465421447168)]} 0 1
[junit4:junit4] 2> 15220 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[56 (1428725465424592896)]} 0 0
[junit4:junit4] 2> 15220 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10056 (1428725465423544320)]} 0 1
[junit4:junit4] 2> 15301 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[52 (-1428725465509527552)]} 0 0
[junit4:junit4] 2> 15301 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10052 (-1428725465509527553)]} 0 0
[junit4:junit4] 2> 15304 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[52 (-1428725465511624704)]} 0 1
[junit4:junit4] 2> 15304 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10052 (-1428725465511624705)]} 0 1
[junit4:junit4] 2> 15306 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10057 (1428725465514770433)]} 0 1
[junit4:junit4] 2> 15306 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[57 (1428725465514770432)]} 0 1
[junit4:junit4] 2> 15309 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[57 (1428725465516867584)]} 0 1
[junit4:junit4] 2> 15309 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10057 (1428725465516867585)]} 0 1
[junit4:junit4] 2> 15349 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[53 (-1428725465559859200)]} 0 0
[junit4:junit4] 2> 15349 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10053 (-1428725465559859201)]} 0 0
[junit4:junit4] 2> 15351 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10053 (-1428725465561956353)]} 0 0
[junit4:junit4] 2> 15351 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[53 (-1428725465561956352)]} 0 0
[junit4:junit4] 2> 15353 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[58 (1428725465564053504)]} 0 0
[junit4:junit4] 2> 15354 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10058 (1428725465564053505)]} 0 0
[junit4:junit4] 2> 15356 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[58 (1428725465567199232)]} 0 1
[junit4:junit4] 2> 15356 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10058 (1428725465567199233)]} 0 0
[junit4:junit4] 2> 15426 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[59 (1428725465640599552)]} 0 0
[junit4:junit4] 2> 15427 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10059 (1428725465640599553)]} 0 1
[junit4:junit4] 2> 15429 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10059 (1428725465643745280)]} 0 1
[junit4:junit4] 2> 15429 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[59 (1428725465643745281)]} 0 0
[junit4:junit4] 2> 15464 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10060 (1428725465680445440)]} 0 0
[junit4:junit4] 2> 15465 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[60 (1428725465680445441)]} 0 1
[junit4:junit4] 2> 15467 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10060 (1428725465682542592)]} 0 1
[junit4:junit4] 2> 15467 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[60 (1428725465682542593)]} 0 1
[junit4:junit4] 2> 15471 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[10061 (1428725465686736896)]} 0 1
[junit4:junit4] 2> 15471 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[61 (1428725465687785472)]} 0 0
[junit4:junit4] 2> 15473 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10061 (1428725465689882624)]} 0 0
[junit4:junit4] 2> 15473 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[61 (1428725465689882625)]} 0 0
[junit4:junit4] 2> 15565 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10062 (1428725465786351616)]} 0 0
[junit4:junit4] 2> 15566 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[62 (1428725465786351617)]} 0 1
[junit4:junit4] 2> 15568 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10062 (1428725465788448768)]} 0 1
[junit4:junit4] 2> 15568 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[62 (1428725465789497344)]} 0 0
[junit4:junit4] 2> 15656 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10055 (-1428725465881772032)]} 0 0
[junit4:junit4] 2> 15656 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[55 (-1428725465881772033)]} 0 0
[junit4:junit4] 2> 15658 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[55 (-1428725465883869184)]} 0 0
[junit4:junit4] 2> 15658 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10055 (-1428725465883869185)]} 0 0
[junit4:junit4] 2> 15660 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[63 (1428725465885966336)]} 0 0
[junit4:junit4] 2> 15661 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10063 (1428725465885966337)]} 0 1
[junit4:junit4] 2> 15662 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[63 (1428725465888063488)]} 0 0
[junit4:junit4] 2> 15663 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10063 (1428725465889112064)]} 0 1
[junit4:junit4] 2> 15689 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[64 (1428725465915326464)]} 0 1
[junit4:junit4] 2> 15689 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10064 (1428725465916375040)]} 0 0
[junit4:junit4] 2> 15691 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[64 (1428725465918472192)]} 0 0
[junit4:junit4] 2> 15692 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10064 (1428725465918472193)]} 0 1
[junit4:junit4] 2> 15706 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[65 (1428725465934200832)]} 0 0
[junit4:junit4] 2> 15707 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10065 (1428725465935249408)]} 0 1
[junit4:junit4] 2> 15708 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[65 (1428725465936297984)]} 0 0
[junit4:junit4] 2> 15709 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[10065 (1428725465937346560)]} 0 0
[junit4:junit4] 2> 15724 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[66 (1428725465952026624)]} 0 1
[junit4:junit4] 2> 15724 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[10066 (1428725465953075200)]} 0 0
[junit4:junit4] 2> 15726 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[66 (1428725465955172352)]} 0 0
[junit4:junit4] 2> 15727 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10066 (1428725465955172353)]} 0 1
[junit4:junit4] 2> 15780 T2923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15781 T2923 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:46739_u",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46739/u"}
[junit4:junit4] 2> 15784 T2922 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> 15784 T2942 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> 15784 T2929 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> 15784 T2958 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> 15804 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[57 (-1428725466035912704)]} 0 1
[junit4:junit4] 2> 15804 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10057 (-1428725466036961280)]} 0 0
[junit4:junit4] 2> C445_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46739_u, base_url=http://127.0.0.1:46739/u}
[junit4:junit4] 2> 15808 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[57 (-1428725466039058432)]} 0 1
[junit4:junit4] 2> 15808 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10057 (-1428725466039058433)]} 0 1
[junit4:junit4] 2> 15808 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[57 (-1428725466039058432)]} 0 2
[junit4:junit4] 2> 15808 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10057 (-1428725466039058433)]} 0 2
[junit4:junit4] 2> 15810 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[67 (1428725466043252736)]} 0 0
[junit4:junit4] 2> 15811 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10067 (1428725466043252737)]} 0 1
[junit4:junit4] 2> 15815 T2954 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1428725466045349888)]} 0 1
[junit4:junit4] 2> 15815 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10067 (1428725466046398464)]} 0 0
[junit4:junit4] 2> 15816 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[67 (1428725466045349888)]} 0 4
[junit4:junit4] 2> 15816 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10067 (1428725466046398464)]} 0 3
[junit4:junit4] 2> 15819 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[58 (-1428725466052689920)]} 0 0
[junit4:junit4] 2> 15819 T2915 C446 P60402 /update {wt=javabin&version=2} {delete=[10058 (-1428725466052689921)]} 0 0
[junit4:junit4] 2> 15821 T2900 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15821 T2900 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15892 T2951 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[58 (-1428725466053738496)]} 0 0
[junit4:junit4] 2> 15892 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10058 (-1428725466054787072)]} 0 0
[junit4:junit4] 2> 15893 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[58 (-1428725466053738496)]} 0 73
[junit4:junit4] 2> 15893 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10058 (-1428725466054787072)]} 0 72
[junit4:junit4] 2> 15894 T2900 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4c0224
[junit4:junit4] 2> 15895 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[68 (1428725466132381696)]} 0 0
[junit4:junit4] 2> 15896 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10068 (1428725466132381697)]} 0 1
[junit4:junit4] 2> 15897 T2900 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 15898 T2900 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 15898 T2900 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 15899 T2900 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2
[junit4:junit4] 2> 15899 T2953 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1428725466134478848)]} 0 0
[junit4:junit4] 2> 15900 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[68 (1428725466134478848)]} 0 3
[junit4:junit4] 2> 15900 T2952 C445 P46739 /update {distrib.from=http://127.0.0.1:59746/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10068 (1428725466134478849)]} 0 1
[junit4:junit4] 2> 15900 T2952 C445 P46739 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4c0224
[junit4:junit4] 2> 15901 T2952 C445 P46739 oasc.SolrException.log SEVERE org.apache.solr.common.SolrException: Failed to unregister info bean: /get
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.unregister(JmxMonitoredMap.java:178)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.clear(JmxMonitoredMap.java:116)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.close(SolrCore.java:959)
[junit4:junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:322)
[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:722)
[junit4:junit4] 2> Caused by: javax.management.InstanceNotFoundException: solr/collection1:type=/get,id=org.apache.solr.handler.RealTimeGetHandler
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1095)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:427)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:537)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.unregister(JmxMonitoredMap.java:175)
[junit4:junit4] 2> ... 28 more
[junit4:junit4] 2>
[junit4:junit4] 2> 15902 T2952 C445 P46739 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=4,adds=4,deletesById=4,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=20,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 15903 T2952 C445 P46739 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 15903 T2900 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=4,deletesById=4,deletesByQuery=0,errors=0,cumulative_adds=46,cumulative_deletesById=20,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 15904 T2952 C445 P46739 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 15904 T2952 C445 P46739 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 15906 T2952 C445 P46739 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79),segFN=segments_3,generation=3,filenames=[_1.doc, _0.cbnd, _0.dvdm, _0.cbnm, _1.fnm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _0_1.del, _1_1.del, _1.dvdd, _1.fdx, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, _0.fdx, _0.tip, segments_3, _0.fdt]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79),segFN=segments_4,generation=4,filenames=[_2.si, _2.pos, _1.doc, _0.cbnd, _0.dvdm, _2.dvdd, _0.cbnm, _1.fnm, _2.doc, _2.tim, _2.dvdm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _2.fdt, _0_1.del, _1_1.del, _2.fdx, _2.fnm, _1.dvdd, _2.tip, _1.fdx, _2.cbnm, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, _0.fdx, _2.cbnd, _0.tip, _0.fdt, segments_4]
[junit4:junit4] 2> 15907 T2952 C445 P46739 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_2.si, _2.pos, _1.doc, _0.cbnd, _0.dvdm, _2.dvdd, _0.cbnm, _1.fnm, _2.doc, _2.tim, _2.dvdm, _1.pos, _1.cbnm, _0.si, _1.cbnd, _1.tip, _0.doc, _1.tim, _0.dvdd, _0.fnm, _2.fdt, _0_1.del, _1_1.del, _2.fdx, _2.fnm, _1.dvdd, _2.tip, _1.fdx, _2.cbnm, _0.pos, _1.fdt, _1.si, _1.dvdm, _0.tim, _0.fdx, _2.cbnd, _0.tip, _0.fdt, segments_4]
[junit4:junit4] 2> 15908 T2952 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 15908 T2952 C445 P46739 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 15908 T2900 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 15908 T2952 C445 P46739 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1362538766356/jetty2/index.20130306025941202
[junit4:junit4] 2> 15909 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10068 (1428725466134478849)]} 0 12
[junit4:junit4] 2> 15909 T2905 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3da3a01d0008
[junit4:junit4] 2> 15911 T2929 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> 15911 T2902 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:45464 which had sessionid 0x13d3da3a01d0008
[junit4:junit4] 2> 15911 T2900 oaz.ZooKeeper.close Session: 0x13d3da3a01d0008 closed
[junit4:junit4] 2> 15911 T2922 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15911 T2942 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15912 T2922 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> 15912 T2942 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> 15912 T2929 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15916 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[61 (-1428725466154401792)]} 0 0
[junit4:junit4] 2> 15918 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[61 (-1428725466156498944)]} 0 0
[junit4:junit4] 2> 15920 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[69 (1428725466157547520)]} 0 1
[junit4:junit4] 2> 15923 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[69 (1428725466161741824)]} 0 0
[junit4:junit4] 2> 15925 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10061 (-1428725466163838976)]} 0 0
[junit4:junit4] 2> 15927 T2937 C447 P59746 /update {wt=javabin&version=2} {delete=[10061 (-1428725466165936128)]} 0 0
[junit4:junit4] 2> 15930 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10069 (1428725466168033280)]} 0 1
[junit4:junit4] 2> 15932 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[10069 (1428725466171179008)]} 0 0
[junit4:junit4] 2> 15934 T2900 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/u,null}
[junit4:junit4] 2> 15961 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[62 (-1428725466201587712)]} 0 1
[junit4:junit4] 2> 15963 T2936 C447 P59746 /update {wt=javabin&version=2} {delete=[62 (-1428725466203684864)]} 0 0
[junit4:junit4] 2> 15967 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[70 (1428725466206830592)]} 0 1
[junit4:junit4] 2> 15970 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10062 (-1428725466211024896)]} 0 0
[junit4:junit4] 2> 15970 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[70 (1428725466209976320)]} 0 1
[junit4:junit4] 2> 15973 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10062 (-1428725466214170624)]} 0 0
[junit4:junit4] 2> 15976 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10070 (1428725466216267776)]} 0 1
[junit4:junit4] 2> 15980 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10070 (1428725466220462080)]} 0 1
[junit4:junit4] 2> 16009 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[71 (1428725466250870784)]} 0 1
[junit4:junit4] 2> 16011 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[71 (1428725466254016512)]} 0 0
[junit4:junit4] 2> 16018 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10071 (1428725466260307968)]} 0 1
[junit4:junit4] 2> 16020 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10071 (1428725466263453696)]} 0 0
[junit4:junit4] 2> 16032 T2916 C446 P60402 /update {wt=javabin&version=2} {add=[72 (1428725466276036608)]} 0 1
[junit4:junit4] 2> 16034 T2935 C447 P59746 /update {wt=javabin&version=2} {add=[72 (1428725466278133760)]} 0 0
[junit4:junit4] 2> 16040 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10072 (1428725466284425216)]} 0 0
[junit4:junit4] 2> 16043 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10072 (1428725466286522368)]} 0 1
[junit4:junit4] 2> 16060 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[65 (-1428725466305396736)]} 0 0
[junit4:junit4] 2> 16062 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[65 (-1428725466307493888)]} 0 0
[junit4:junit4] 2> 16064 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[73 (1428725466309591040)]} 0 0
[junit4:junit4] 2> 16066 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[73 (1428725466311688192)]} 0 0
[junit4:junit4] 2> 16069 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[10065 (-1428725466314833920)]} 0 0
[junit4:junit4] 2> 16071 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[10065 (-1428725466316931072)]} 0 0
[junit4:junit4] 2> 16073 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[10073 (1428725466317979648)]} 0 1
[junit4:junit4] 2> 16075 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[10073 (1428725466321125376)]} 0 0
[junit4:junit4] 2> 16137 T2918 C446 P60402 /update {wt=javabin&version=2} {add=[74 (1428725466386137088)]} 0 0
[junit4:junit4] 2> 16141 T2938 C447 P59746 /update {wt=javabin&version=2} {add=[74 (1428725466389282816)]} 0 1
[junit4:junit4] 2> 16146 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10074 (1428725466394525696)]} 0 1
[junit4:junit4] 2> 16149 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10074 (1428725466397671424)]} 0 1
[junit4:junit4] 2> 16178 T2916 C446 P60402 /update {wt=javabin&version=2} {delete=[66 (-1428725466429128704)]} 0 0
[junit4:junit4] 2> 16181 T2935 C447 P59746 /update {wt=javabin&version=2} {delete=[66 (-1428725466432274432)]} 0 0
[junit4:junit4] 2> 16184 T2917 C446 P60402 /update {wt=javabin&version=2} {add=[75 (1428725466434371584)]} 0 1
[junit4:junit4] 2> 16187 T2918 C446 P60402 /update {wt=javabin&version=2} {delete=[10066 (-1428725466438565888)]} 0 0
[junit4:junit4] 2> 16187 T2937 C447 P59746 /update {wt=javabin&version=2} {add=[75 (1428725466437517312)]} 0 1
[junit4:junit4] 2> 16187 T2900 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 16189 T2938 C447 P59746 /update {wt=javabin&version=2} {delete=[10066 (-1428725466440663040)]} 0 0
[junit4:junit4] 2> 16191 T2900 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46739
[junit4:junit4] 2> 16192 T2900 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 16192 T2915 C446 P60402 /update {wt=javabin&version=2} {add=[10075 (1428725466443808768)]} 0 0
[junit4:junit4] 2> 16193 T2900 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 16193 T2900 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473
[junit4:junit4] 2> 16194 T2900 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/solr.xml
[junit4:junit4] 2> 16195 T2900 oasc.CoreContainer.<init> New CoreContainer 5472413
[junit4:junit4] 2> 16195 T2936 C447 P59746 /update {wt=javabin&version=2} {add=[10075 (1428725466446954496)]} 0 0
[junit4:junit4] 2> 16195 T2900 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/'
[junit4:junit4] 2> 16197 T2900 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1362538774473/'
[junit4:junit4] 2> 16233 T2900 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 16234 T2900 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 16234 T2900 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 16235 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 16235 T2900 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 16235 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 16236 T2900 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 16236 T2900 oashc.HttpSh
[...truncated too long message...]
est params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=mt, timezone=Portugal
[junit4:junit4] 2> NOTE: Linux 3.2.0-38-generic i386/Oracle Corporation 1.7.0_15 (32-bit)/cpus=8,threads=3,free=37111304,total=187924480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestUpdate, TestCollationField, TestCSVLoader, TestRangeQuery, TestOmitPositions, TestDistributedSearch, TestRecovery, XmlUpdateRequestHandlerTest, CollectionsAPIDistributedZkTest, CurrencyFieldXmlFileTest, TestWordDelimiterFilterFactory, TestFoldingMultitermQuery, DistanceFunctionTest, FullSolrCloudDistribCmdsTest, TestCodecSupport, SolrIndexConfigTest, TestDefaultSimilarityFactory, SuggesterWFSTTest, DirectSolrSpellCheckerTest, TestSolrXMLSerializer, ClusterStateTest, FieldAnalysisRequestHandlerTest, CopyFieldTest, ShardRoutingCustomTest, CurrencyFieldOpenExchangeTest, HighlighterTest, TestBinaryResponseWriter, IndexReaderFactoryTest, HighlighterConfigTest, IndexSchemaRuntimeFieldTest, SampleTest, DOMUtilTest, OutputWriterTest, TestBM25SimilarityFactory, TermVectorComponentDistributedTest, BasicDistributedZk2Test, LeaderElectionIntegrationTest, TestIndexSearcher, NotRequiredUniqueKeyTest, TestAnalyzedSuggestions, URLClassifyProcessorTest, TestZkChroot, TestBinaryField, TestUtils, RequestHandlersTest, MultiTermTest, TestStressLucene, TestJmxMonitoredMap, TestSystemIdResolver, BadIndexSchemaTest, TestElisionMultitermQuery, TestHashPartitioner, EchoParamsTest, TestSolrJ, SolrCmdDistributorTest, DirectUpdateHandlerTest, TestLuceneMatchVersion, ChaosMonkeySafeLeaderTest, TestPartialUpdateDeduplication, UniqFieldsUpdateProcessorFactoryTest, ZkNodePropsTest, DebugComponentTest, UnloadDistributedZkTest, OpenCloseCoreStressTest, BasicZkTest, RecoveryZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.seed=AF1F7D4FEFA3160C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mt -Dtests.timezone=Portugal -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 0.00s J1 | RecoveryZkTest (suite) <<<
[junit4:junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ResourceDisposalError: Resource in scope SUITE failed to close. Resource was registered from thread Thread[id=2959, name=coreLoadExecutor-2287-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1567)
[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:334)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4:junit4] > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(org.apache.lucene.store.RAMDirectory@9748d7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1836c77)
[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=2961, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1567)
[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@10dfb8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@6e9e79)
[junit4:junit4] > at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4] > at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] Completed on J1 in 36.26s, 1 test, 2 errors <<< FAILURES!
[...truncated 393 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:361: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1213: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:877: There were test failures: 261 suites, 1105 tests, 2 suite-level errors, 13 ignored (7 assumptions)
Total time: 45 minutes 55 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.7.0_15 -client -XX:+UseSerialGC
Email was triggered for: Failure
Sending email for trigger: Failure