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/23 20:41:50 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.6.0_41) - Build # 4796
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4796/
Java: 64bit/jdk1.6.0_41 -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=2678, name=coreLoadExecutor-2162-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=2678, name=coreLoadExecutor-2162-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1479)
at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:525)
at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:329)
at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:746)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:872)
at org.apache.solr.core.CoreContainer.create(CoreContainer.java:955)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:579)
at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227539tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@1df1d32b))
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=2680, 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=2680, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
at java.lang.Thread.getStackTrace(Thread.java:1479)
at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:525)
at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:329)
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(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042))
at org.junit.Assert.fail(Assert.java:93)
at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:662)
Build Log:
[...truncated 8788 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 0 T2619 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /gpx/sq
[junit4:junit4] 2> 4 T2619 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-RecoveryZkTest-1364067259676
[junit4:junit4] 2> 4 T2619 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 5 T2620 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 5 T2620 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 6 T2620 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 6 T2620 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 6 T2620 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 7 T2620 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-1364067259676/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 105 T2619 oasc.ZkTestServer.run start zk server on port:38691
[junit4:junit4] 2> 106 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@348da8e9
[junit4:junit4] 2> 106 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 107 T2625 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 107 T2625 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 107 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44330
[junit4:junit4] 2> 108 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44330
[junit4:junit4] 2> 108 T2623 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 226 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0000 with negotiated timeout 10000 for client /127.0.0.1:44330
[junit4:junit4] 2> 226 T2625 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0000, negotiated timeout = 10000
[junit4:junit4] 2> 226 T2626 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@348da8e9 name:ZooKeeperConnection Watcher:127.0.0.1:38691 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 226 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 227 T2619 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 232 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0000
[junit4:junit4] 2> 233 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44330 which had sessionid 0x13d98be951f0000
[junit4:junit4] 2> 233 T2626 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 233 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0000 closed
[junit4:junit4] 2> 234 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@56c3784c
[junit4:junit4] 2> 235 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 235 T2627 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 235 T2627 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 236 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44331
[junit4:junit4] 2> 236 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44331
[junit4:junit4] 2> 237 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0001 with negotiated timeout 10000 for client /127.0.0.1:44331
[junit4:junit4] 2> 237 T2627 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0001, negotiated timeout = 10000
[junit4:junit4] 2> 238 T2628 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@56c3784c name:ZooKeeperConnection Watcher:127.0.0.1:38691/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 238 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 238 T2619 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 243 T2619 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 247 T2619 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 250 T2619 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 253 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 254 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 260 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 261 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 266 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 267 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 271 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 272 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 275 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 276 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 280 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 281 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 284 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 285 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 289 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 290 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 294 T2619 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 294 T2619 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 298 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0001
[junit4:junit4] 2> 299 T2628 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 299 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44331 which had sessionid 0x13d98be951f0001
[junit4:junit4] 2> 299 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0001 closed
[junit4:junit4] 2> 373 T2619 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 377 T2619 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48820
[junit4:junit4] 2> 378 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 378 T2619 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 378 T2619 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972
[junit4:junit4] 2> 379 T2619 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/solr.xml
[junit4:junit4] 2> 379 T2619 oasc.CoreContainer.<init> New CoreContainer 1893477123
[junit4:junit4] 2> 379 T2619 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/'
[junit4:junit4] 2> 380 T2619 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/'
[junit4:junit4] 2> 395 T2619 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 396 T2619 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 396 T2619 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 396 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 396 T2619 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 397 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 397 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 397 T2619 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 398 T2619 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 398 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 403 T2619 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 413 T2619 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38691/solr
[junit4:junit4] 2> 414 T2619 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 414 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@47fe2d18
[junit4:junit4] 2> 415 T2638 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 415 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 416 T2638 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 416 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44332
[junit4:junit4] 2> 416 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44332
[junit4:junit4] 2> 417 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0002 with negotiated timeout 20000 for client /127.0.0.1:44332
[junit4:junit4] 2> 417 T2638 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0002, negotiated timeout = 20000
[junit4:junit4] 2> 417 T2639 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47fe2d18 name:ZooKeeperConnection Watcher:127.0.0.1:38691 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 417 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 418 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0002
[junit4:junit4] 2> 419 T2639 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 419 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44332 which had sessionid 0x13d98be951f0002
[junit4:junit4] 2> 419 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0002 closed
[junit4:junit4] 2> 420 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 422 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4bb72f93
[junit4:junit4] 2> 423 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 424 T2640 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 424 T2640 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 424 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44333
[junit4:junit4] 2> 425 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44333
[junit4:junit4] 2> 426 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0003 with negotiated timeout 20000 for client /127.0.0.1:44333
[junit4:junit4] 2> 426 T2640 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0003, negotiated timeout = 20000
[junit4:junit4] 2> 426 T2641 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bb72f93 name:ZooKeeperConnection Watcher:127.0.0.1:38691/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 426 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 429 T2619 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 432 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 432 T2619 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 435 T2619 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 437 T2619 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48820_gpx%2Fsq
[junit4:junit4] 2> 438 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:48820_gpx%2Fsq Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:48820_gpx%2Fsq
[junit4:junit4] 2> 438 T2619 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48820_gpx%2Fsq
[junit4:junit4] 2> 460 T2619 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 469 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 470 T2619 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 474 T2619 oasc.Overseer.start Overseer (id=89395511930322947-127.0.0.1:48820_gpx%2Fsq-n_0000000000) starting
[junit4:junit4] 2> 475 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 476 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 477 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 479 T2619 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 483 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 484 T2643 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 485 T2619 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 489 T2619 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 491 T2619 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 495 T2642 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 500 T2644 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/collection1
[junit4:junit4] 2> 501 T2644 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 501 T2644 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 502 T2644 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 503 T2644 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/collection1/'
[junit4:junit4] 2> 504 T2644 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/collection1/lib/README' to classloader
[junit4:junit4] 2> 504 T2644 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 545 T2644 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 576 T2644 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 577 T2644 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 581 T2644 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 939 T2644 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 944 T2644 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 946 T2644 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 954 T2644 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 958 T2644 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 962 T2644 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 963 T2644 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 963 T2644 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 963 T2644 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 964 T2644 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 965 T2644 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 965 T2644 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 965 T2644 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1364067259972/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/control/data/
[junit4:junit4] 2> 966 T2644 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a2bccb2
[junit4:junit4] 2> 966 T2644 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 967 T2644 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/control/data
[junit4:junit4] 2> 968 T2644 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/control/data/index/
[junit4:junit4] 2> 968 T2644 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1364067259676/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 968 T2644 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/control/data/index
[junit4:junit4] 2> 971 T2644 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7bbf515a lockFactory=org.apache.lucene.store.NativeFSLockFactory@56765992; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 971 T2644 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 973 T2644 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 974 T2644 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 974 T2644 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 975 T2644 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 975 T2644 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 976 T2644 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 976 T2644 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 977 T2644 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 977 T2644 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 980 T2644 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 982 T2644 oass.SolrIndexSearcher.<init> Opening Searcher@212adfc0 main
[junit4:junit4] 2> 982 T2644 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/control/data/tlog
[junit4:junit4] 2> 983 T2644 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 983 T2644 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 987 T2645 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@212adfc0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 988 T2644 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 988 T2644 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2001 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2002 T2642 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:48820_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48820/gpx/sq"}
[junit4:junit4] 2> 2002 T2642 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2003 T2642 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2007 T2641 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> 2989 T2644 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2990 T2644 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48820/gpx/sq collection:control_collection shard:shard1
[junit4:junit4] 2> 2991 T2644 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2995 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2996 T2644 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2996 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2998 T2644 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2998 T2644 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2998 T2644 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48820/gpx/sq/collection1/
[junit4:junit4] 2> 2998 T2644 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2999 T2644 oasc.SyncStrategy.syncToMe http://127.0.0.1:48820/gpx/sq/collection1/ has no replicas
[junit4:junit4] 2> 2999 T2644 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48820/gpx/sq/collection1/
[junit4:junit4] 2> 2999 T2644 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 3002 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3513 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3524 T2641 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> 3555 T2644 oasc.ZkController.register We are http://127.0.0.1:48820/gpx/sq/collection1/ and leader is http://127.0.0.1:48820/gpx/sq/collection1/
[junit4:junit4] 2> 3555 T2644 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48820/gpx/sq
[junit4:junit4] 2> 3555 T2644 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3556 T2644 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3556 T2644 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3558 T2644 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3560 T2619 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3560 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3561 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3566 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3567 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5b64a8d0
[junit4:junit4] 2> 3568 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3569 T2647 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3569 T2647 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 3569 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44340
[junit4:junit4] 2> 3570 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44340
[junit4:junit4] 2> 3571 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0004 with negotiated timeout 10000 for client /127.0.0.1:44340
[junit4:junit4] 2> 3571 T2647 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0004, negotiated timeout = 10000
[junit4:junit4] 2> 3572 T2648 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b64a8d0 name:ZooKeeperConnection Watcher:127.0.0.1:38691/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3572 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3574 T2619 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3577 T2619 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3652 T2619 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3654 T2619 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52822
[junit4:junit4] 2> 3654 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3654 T2619 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3655 T2619 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250
[junit4:junit4] 2> 3655 T2619 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/solr.xml
[junit4:junit4] 2> 3655 T2619 oasc.CoreContainer.<init> New CoreContainer 1457533645
[junit4:junit4] 2> 3656 T2619 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/'
[junit4:junit4] 2> 3656 T2619 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/'
[junit4:junit4] 2> 3671 T2619 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3671 T2619 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3671 T2619 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3672 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3672 T2619 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3672 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3673 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3673 T2619 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3673 T2619 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3673 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3678 T2619 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3688 T2619 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38691/solr
[junit4:junit4] 2> 3688 T2619 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3688 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@675db22c
[junit4:junit4] 2> 3689 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3705 T2658 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3706 T2658 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 3706 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44341
[junit4:junit4] 2> 3707 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44341
[junit4:junit4] 2> 3708 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0005 with negotiated timeout 20000 for client /127.0.0.1:44341
[junit4:junit4] 2> 3708 T2658 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0005, negotiated timeout = 20000
[junit4:junit4] 2> 3708 T2659 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@675db22c name:ZooKeeperConnection Watcher:127.0.0.1:38691 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3709 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3710 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0005
[junit4:junit4] 2> 3711 T2659 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3711 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44341 which had sessionid 0x13d98be951f0005
[junit4:junit4] 2> 3711 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0005 closed
[junit4:junit4] 2> 3712 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3714 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4645c508
[junit4:junit4] 2> 3715 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3715 T2660 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3716 T2660 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 3716 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44342
[junit4:junit4] 2> 3716 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44342
[junit4:junit4] 2> 3718 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0006 with negotiated timeout 20000 for client /127.0.0.1:44342
[junit4:junit4] 2> 3718 T2660 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0006, negotiated timeout = 20000
[junit4:junit4] 2> 3718 T2661 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4645c508 name:ZooKeeperConnection Watcher:127.0.0.1:38691/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3718 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3720 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3722 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3725 T2619 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4730 T2619 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52822_gpx%2Fsq
[junit4:junit4] 2> 4731 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52822_gpx%2Fsq Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52822_gpx%2Fsq
[junit4:junit4] 2> 4732 T2619 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52822_gpx%2Fsq
[junit4:junit4] 2> 4738 T2648 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4738 T2641 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4738 T2661 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4738 T2641 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> 4746 T2662 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/collection1
[junit4:junit4] 2> 4746 T2662 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4748 T2662 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4748 T2662 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4750 T2662 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/collection1/'
[junit4:junit4] 2> 4751 T2662 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/collection1/lib/README' to classloader
[junit4:junit4] 2> 4752 T2662 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4776 T2662 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 4805 T2662 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4806 T2662 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4809 T2662 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5030 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5031 T2642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:48820_gpx%2Fsq_collection1",
[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:48820_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48820/gpx/sq"}
[junit4:junit4] 2> 5049 T2641 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> 5049 T2661 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> 5049 T2648 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> 5192 T2662 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5197 T2662 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5199 T2662 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5208 T2662 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5211 T2662 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5214 T2662 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5214 T2662 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5215 T2662 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5215 T2662 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5216 T2662 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5216 T2662 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5216 T2662 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5217 T2662 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1364067263250/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty1/
[junit4:junit4] 2> 5217 T2662 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a2bccb2
[junit4:junit4] 2> 5217 T2662 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5218 T2662 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty1
[junit4:junit4] 2> 5218 T2662 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty1/index/
[junit4:junit4] 2> 5218 T2662 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5219 T2662 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty1/index
[junit4:junit4] 2> 5220 T2662 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7dca5810 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63c882b5; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5220 T2662 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5221 T2662 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5222 T2662 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5222 T2662 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5222 T2662 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5223 T2662 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5223 T2662 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5223 T2662 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5224 T2662 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5224 T2662 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5226 T2662 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5228 T2662 oass.SolrIndexSearcher.<init> Opening Searcher@5ac9ef4a main
[junit4:junit4] 2> 5228 T2662 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty1/tlog
[junit4:junit4] 2> 5228 T2662 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5229 T2662 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5232 T2663 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5ac9ef4a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5233 T2662 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5233 T2662 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6554 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6555 T2642 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:52822_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52822/gpx/sq"}
[junit4:junit4] 2> 6555 T2642 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6556 T2642 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6561 T2661 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> 6561 T2648 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> 6561 T2641 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> 7235 T2662 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7235 T2662 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52822/gpx/sq collection:collection1 shard:shard1
[junit4:junit4] 2> 7236 T2662 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7240 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0006 type:delete cxid:0x4a zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7241 T2662 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7241 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7243 T2662 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7243 T2662 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7243 T2662 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52822/gpx/sq/collection1/
[junit4:junit4] 2> 7243 T2662 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7243 T2662 oasc.SyncStrategy.syncToMe http://127.0.0.1:52822/gpx/sq/collection1/ has no replicas
[junit4:junit4] 2> 7243 T2662 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52822/gpx/sq/collection1/
[junit4:junit4] 2> 7244 T2662 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7246 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8066 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8076 T2661 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> 8077 T2648 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> 8076 T2641 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> 8100 T2662 oasc.ZkController.register We are http://127.0.0.1:52822/gpx/sq/collection1/ and leader is http://127.0.0.1:52822/gpx/sq/collection1/
[junit4:junit4] 2> 8100 T2662 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52822/gpx/sq
[junit4:junit4] 2> 8101 T2662 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8101 T2662 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8101 T2662 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8104 T2662 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8105 T2619 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 8106 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8107 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8182 T2619 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8184 T2619 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47148
[junit4:junit4] 2> 8185 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8185 T2619 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8185 T2619 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784
[junit4:junit4] 2> 8186 T2619 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/solr.xml
[junit4:junit4] 2> 8186 T2619 oasc.CoreContainer.<init> New CoreContainer 885743851
[junit4:junit4] 2> 8186 T2619 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/'
[junit4:junit4] 2> 8187 T2619 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/'
[junit4:junit4] 2> 8202 T2619 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8202 T2619 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8202 T2619 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8203 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8203 T2619 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8203 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8204 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8204 T2619 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8204 T2619 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8205 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8210 T2619 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8236 T2619 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38691/solr
[junit4:junit4] 2> 8236 T2619 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8237 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@756455f2
[junit4:junit4] 2> 8238 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8239 T2674 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8240 T2674 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 8240 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44347
[junit4:junit4] 2> 8241 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44347
[junit4:junit4] 2> 8242 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0007 with negotiated timeout 20000 for client /127.0.0.1:44347
[junit4:junit4] 2> 8242 T2674 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0007, negotiated timeout = 20000
[junit4:junit4] 2> 8242 T2675 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@756455f2 name:ZooKeeperConnection Watcher:127.0.0.1:38691 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8243 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8245 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0007
[junit4:junit4] 2> 8246 T2675 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8246 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44347 which had sessionid 0x13d98be951f0007
[junit4:junit4] 2> 8246 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0007 closed
[junit4:junit4] 2> 8247 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8251 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@f60776e
[junit4:junit4] 2> 8253 T2676 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8253 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8253 T2676 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 8253 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44348
[junit4:junit4] 2> 8254 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44348
[junit4:junit4] 2> 8255 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0008 with negotiated timeout 20000 for client /127.0.0.1:44348
[junit4:junit4] 2> 8255 T2676 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0008, negotiated timeout = 20000
[junit4:junit4] 2> 8256 T2677 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f60776e name:ZooKeeperConnection Watcher:127.0.0.1:38691/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8256 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8258 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8259 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8263 T2619 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9266 T2619 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47148_gpx%2Fsq
[junit4:junit4] 2> 9267 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f0008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:47148_gpx%2Fsq Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:47148_gpx%2Fsq
[junit4:junit4] 2> 9267 T2619 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47148_gpx%2Fsq
[junit4:junit4] 2> 9270 T2648 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> 9271 T2641 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9271 T2677 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9271 T2661 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9271 T2641 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> 9271 T2661 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> 9272 T2648 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9275 T2678 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/collection1
[junit4:junit4] 2> 9276 T2678 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9276 T2678 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9276 T2678 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9278 T2678 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/collection1/'
[junit4:junit4] 2> 9278 T2678 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/collection1/lib/README' to classloader
[junit4:junit4] 2> 9279 T2678 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9309 T2678 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 9338 T2678 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9339 T2678 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9342 T2678 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9583 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9583 T2642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:52822_gpx%2Fsq_collection1",
[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:52822_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52822/gpx/sq"}
[junit4:junit4] 2> 9586 T2661 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> 9586 T2648 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> 9586 T2641 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> 9586 T2677 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> 9697 T2678 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9702 T2678 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9705 T2678 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9716 T2678 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9719 T2678 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9721 T2678 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9722 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9723 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9723 T2678 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9724 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9724 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9724 T2678 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9725 T2678 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/
[junit4:junit4] 2> 9725 T2678 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a2bccb2
[junit4:junit4] 2> 9725 T2678 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9726 T2678 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2
[junit4:junit4] 2> 9727 T2678 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index/
[junit4:junit4] 2> 9727 T2678 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9727 T2678 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index
[junit4:junit4] 2> 9729 T2678 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@927d2b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@472c61b6; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9729 T2678 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9731 T2678 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9731 T2678 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9731 T2678 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9732 T2678 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9732 T2678 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9733 T2678 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9733 T2678 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9733 T2678 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9734 T2678 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9736 T2678 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9739 T2678 oass.SolrIndexSearcher.<init> Opening Searcher@5c9b21a7 main
[junit4:junit4] 2> 9739 T2678 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/tlog
[junit4:junit4] 2> 9740 T2678 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9740 T2678 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9745 T2679 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c9b21a7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9747 T2678 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9747 T2678 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11089 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11090 T2642 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:47148_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47148/gpx/sq"}
[junit4:junit4] 2> 11090 T2642 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11090 T2642 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11094 T2661 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> 11094 T2648 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> 11094 T2641 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> 11094 T2677 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> 11748 T2678 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11749 T2678 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47148/gpx/sq collection:collection1 shard:shard1
[junit4:junit4] 2> 11752 T2678 oasc.ZkController.register We are http://127.0.0.1:47148/gpx/sq/collection1/ and leader is http://127.0.0.1:52822/gpx/sq/collection1/
[junit4:junit4] 2> 11752 T2678 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47148/gpx/sq
[junit4:junit4] 2> 11752 T2678 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11752 T2678 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C395 name=collection1 org.apache.solr.core.SolrCore@333b25ba url=http://127.0.0.1:47148/gpx/sq/collection1 node=127.0.0.1:47148_gpx%2Fsq C395_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:47148_gpx%2Fsq, base_url=http://127.0.0.1:47148/gpx/sq}
[junit4:junit4] 2> 11752 T2680 C395 P47148 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11753 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11753 T2678 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11753 T2680 C395 P47148 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11753 T2680 C395 P47148 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11754 T2619 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 11754 T2680 C395 P47148 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11754 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11754 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11758 T2619 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C396 name=collection1 org.apache.solr.core.SolrCore@241affa9 url=http://127.0.0.1:48820/gpx/sq/collection1 node=127.0.0.1:48820_gpx%2Fsq C396_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:48820_gpx%2Fsq, base_url=http://127.0.0.1:48820/gpx/sq, leader=true}
[junit4:junit4] 2> 11767 T2635 C396 P48820 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7bbf515a lockFactory=org.apache.lucene.store.NativeFSLockFactory@56765992; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11768 T2635 C396 P48820 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11769 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10001 (1430328203215372289)]} 0 3
[junit4:junit4] 2> 11769 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[1 (1430328203215372288)]} 0 3
[junit4:junit4] 2> ASYNC NEW_CORE C397 name=collection1 org.apache.solr.core.SolrCore@12b476ac url=http://127.0.0.1:52822/gpx/sq/collection1 node=127.0.0.1:52822_gpx%2Fsq C397_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52822_gpx%2Fsq, base_url=http://127.0.0.1:52822/gpx/sq, leader=true}
[junit4:junit4] 2> 11776 T2656 C397 P52822 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7dca5810 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63c882b5; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11777 T2656 C397 P52822 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11778 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[1 (1430328203224809472)]} 0 3
[junit4:junit4] 2> 11778 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10001 (1430328203224809473)]} 0 3
[junit4:junit4] 2> 11825 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[2 (1430328203277238272)]} 0 0
[junit4:junit4] 2> 11826 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10002 (1430328203277238273)]} 0 1
[junit4:junit4] 2> 11828 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10002 (1430328203279335424)]} 0 1
[junit4:junit4] 2> 11828 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[2 (1430328203279335425)]} 0 1
[junit4:junit4] 2> 11838 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[3 (1430328203290869760)]} 0 1
[junit4:junit4] 2> 11838 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10003 (1430328203289821184)]} 0 1
[junit4:junit4] 2> 11840 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[3 (1430328203292966912)]} 0 0
[junit4:junit4] 2> 11840 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10003 (1430328203292966913)]} 0 0
[junit4:junit4] 2> 11934 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[4 (1430328203391533056)]} 0 0
[junit4:junit4] 2> 11935 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10004 (1430328203391533057)]} 0 1
[junit4:junit4] 2> 11937 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[4 (1430328203393630208)]} 0 1
[junit4:junit4] 2> 11937 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10004 (1430328203393630209)]} 0 1
[junit4:junit4] 2> 11972 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[5 (1430328203431378945)]} 0 0
[junit4:junit4] 2> 11972 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10005 (1430328203431378944)]} 0 0
[junit4:junit4] 2> 11974 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[5 (1430328203433476096)]} 0 0
[junit4:junit4] 2> 11974 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10005 (1430328203433476097)]} 0 0
[junit4:junit4] 2> 12054 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[4 (-1430328203517362176)]} 0 0
[junit4:junit4] 2> 12054 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10004 (-1430328203517362177)]} 0 0
[junit4:junit4] 2> 12056 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[4 (-1430328203519459328)]} 0 0
[junit4:junit4] 2> 12056 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[10004 (-1430328203519459329)]} 0 0
[junit4:junit4] 2> 12058 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[6 (1430328203521556480)]} 0 0
[junit4:junit4] 2> 12058 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10006 (1430328203521556481)]} 0 0
[junit4:junit4] 2> 12060 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[6 (1430328203523653632)]} 0 0
[junit4:junit4] 2> 12060 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10006 (1430328203523653633)]} 0 0
[junit4:junit4] 2> 12159 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10007 (1430328203626414080)]} 0 1
[junit4:junit4] 2> 12159 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[7 (1430328203626414081)]} 0 1
[junit4:junit4] 2> 12161 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10007 (1430328203629559808)]} 0 0
[junit4:junit4] 2> 12161 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[7 (1430328203629559809)]} 0 0
[junit4:junit4] 2> 12262 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[8 (1430328203735465985)]} 0 0
[junit4:junit4] 2> 12262 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10008 (1430328203735465984)]} 0 0
[junit4:junit4] 2> 12264 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[8 (1430328203737563136)]} 0 0
[junit4:junit4] 2> 12265 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10008 (1430328203737563137)]} 0 1
[junit4:junit4] 2> 12354 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10009 (1430328203830886401)]} 0 1
[junit4:junit4] 2> 12354 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[9 (1430328203830886400)]} 0 1
[junit4:junit4] 2> 12356 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10009 (1430328203834032128)]} 0 0
[junit4:junit4] 2> 12356 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[9 (1430328203834032129)]} 0 0
[junit4:junit4] 2> 12451 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10005 (-1430328203932598272)]} 0 1
[junit4:junit4] 2> 12451 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[5 (-1430328203933646848)]} 0 1
[junit4:junit4] 2> 12453 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10005 (-1430328203935744000)]} 0 0
[junit4:junit4] 2> 12453 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[5 (-1430328203935744001)]} 0 0
[junit4:junit4] 2> 12455 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10010 (1430328203937841152)]} 0 0
[junit4:junit4] 2> 12456 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10 (1430328203937841153)]} 0 1
[junit4:junit4] 2> 12458 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10010 (1430328203940986880)]} 0 0
[junit4:junit4] 2> 12458 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10 (1430328203940986881)]} 0 0
[junit4:junit4] 2> 12510 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10006 (-1430328203994464256)]} 0 1
[junit4:junit4] 2> 12510 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[6 (-1430328203995512832)]} 0 0
[junit4:junit4] 2> 12512 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10006 (-1430328203997609984)]} 0 0
[junit4:junit4] 2> 12512 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[6 (-1430328203997609985)]} 0 0
[junit4:junit4] 2> 12514 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10011 (1430328203999707136)]} 0 0
[junit4:junit4] 2> 12515 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[11 (1430328203999707137)]} 0 1
[junit4:junit4] 2> 12517 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10011 (1430328204002852864)]} 0 1
[junit4:junit4] 2> 12517 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[11 (1430328204002852865)]} 0 0
[junit4:junit4] 2> 12532 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10007 (-1430328204018581504)]} 0 0
[junit4:junit4] 2> 12533 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[7 (-1430328204019630080)]} 0 0
[junit4:junit4] 2> 12535 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[10007 (-1430328204021727232)]} 0 1
[junit4:junit4] 2> 12535 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[7 (-1430328204021727233)]} 0 0
[junit4:junit4] 2> 12537 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10012 (1430328204023824384)]} 0 0
[junit4:junit4] 2> 12538 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[12 (1430328204023824385)]} 0 1
[junit4:junit4] 2> 12540 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10012 (1430328204025921536)]} 0 1
[junit4:junit4] 2> 12540 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[12 (1430328204026970112)]} 0 0
[junit4:junit4] 2> 12573 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10013 (1430328204060524544)]} 0 1
[junit4:junit4] 2> 12573 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[13 (1430328204061573120)]} 0 1
[junit4:junit4] 2> 12575 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10013 (1430328204063670272)]} 0 0
[junit4:junit4] 2> 12576 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[13 (1430328204063670273)]} 0 1
[junit4:junit4] 2> 12598 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12600 T2642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47148_gpx%2Fsq_collection1",
[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:47148_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47148/gpx/sq"}
[junit4:junit4] 2> 12606 T2641 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> 12606 T2677 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> 12606 T2648 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> 12606 T2661 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> 12616 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10014 (1430328204106661888)]} 0 1
[junit4:junit4] 2> 12616 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[14 (1430328204106661889)]} 0 0
[junit4:junit4] 2> C395_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:47148_gpx%2Fsq, base_url=http://127.0.0.1:47148/gpx/sq}
[junit4:junit4] 2> 12645 T2673 C395 P47148 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@927d2b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@472c61b6; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12645 T2673 C395 P47148 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12647 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1430328204129730560)]} 0 3
[junit4:junit4] 2> 12647 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10014 (1430328204129730561)]} 0 3
[junit4:junit4] 2> 12647 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[14 (1430328204129730560)]} 0 9
[junit4:junit4] 2> 12647 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10014 (1430328204129730561)]} 0 9
[junit4:junit4] 2> 12741 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[8 (-1430328204237733888)]} 0 0
[junit4:junit4] 2> 12741 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10008 (-1430328204237733889)]} 0 0
[junit4:junit4] 2> 12746 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10008 (-1430328204240879617)]} 0 1
[junit4:junit4] 2> 12746 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[8 (-1430328204240879616)]} 0 0
[junit4:junit4] 2> 12746 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[10008 (-1430328204240879617)]} 0 2
[junit4:junit4] 2> 12747 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[8 (-1430328204240879616)]} 0 3
[junit4:junit4] 2> 12749 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10015 (1430328204246122496)]} 0 0
[junit4:junit4] 2> 12750 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[15 (1430328204246122497)]} 0 1
[junit4:junit4] 2> 12754 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10015 (1430328204248219648)]} 0 1
[junit4:junit4] 2> 12754 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1430328204249268224)]} 0 0
[junit4:junit4] 2> 12755 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10015 (1430328204248219648)]} 0 4
[junit4:junit4] 2> 12755 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[15 (1430328204249268224)]} 0 3
[junit4:junit4] 2> 12759 T2654 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=127.0.0.1:47148_gpx%252Fsq_collection1&state=recovering&nodeName=127.0.0.1:47148_gpx%252Fsq&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 12780 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10009 (-1430328204278628352)]} 0 0
[junit4:junit4] 2> 12780 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[9 (-1430328204278628353)]} 0 0
[junit4:junit4] 2> 12784 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10009 (-1430328204280725504)]} 0 0
[junit4:junit4] 2> 12785 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[9 (-1430328204281774080)]} 0 1
[junit4:junit4] 2> 12785 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10009 (-1430328204280725504)]} 0 3
[junit4:junit4] 2> 12785 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[9 (-1430328204281774080)]} 0 2
[junit4:junit4] 2> 12787 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10016 (1430328204285968384)]} 0 0
[junit4:junit4] 2> 12788 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[16 (1430328204285968385)]} 0 1
[junit4:junit4] 2> 12792 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10016 (1430328204289114112)]} 0 0
[junit4:junit4] 2> 12792 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1430328204289114113)]} 0 0
[junit4:junit4] 2> 12793 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10016 (1430328204289114112)]} 0 4
[junit4:junit4] 2> 12793 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[16 (1430328204289114113)]} 0 3
[junit4:junit4] 2> 12852 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10017 (1430328204354125824)]} 0 0
[junit4:junit4] 2> 12853 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[17 (1430328204354125825)]} 0 1
[junit4:junit4] 2> 12857 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10017 (1430328204356222976)]} 0 1
[junit4:junit4] 2> 12857 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1430328204357271552)]} 0 0
[junit4:junit4] 2> 12858 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10017 (1430328204356222976)]} 0 4
[junit4:junit4] 2> 12858 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[17 (1430328204357271552)]} 0 3
[junit4:junit4] 2> 12872 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10010 (-1430328204375097344)]} 0 0
[junit4:junit4] 2> 12873 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10 (-1430328204375097345)]} 0 1
[junit4:junit4] 2> 12876 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10010 (-1430328204377194496)]} 0 0
[junit4:junit4] 2> 12876 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10 (-1430328204378243072)]} 0 0
[junit4:junit4] 2> 12876 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10010 (-1430328204377194496)]} 0 2
[junit4:junit4] 2> 12877 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10 (-1430328204378243072)]} 0 2
[junit4:junit4] 2> 12879 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10018 (1430328204382437376)]} 0 0
[junit4:junit4] 2> 12880 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[18 (1430328204382437377)]} 0 1
[junit4:junit4] 2> 12884 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10018 (1430328204384534528)]} 0 1
[junit4:junit4] 2> 12884 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1430328204385583104)]} 0 0
[junit4:junit4] 2> 12885 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10018 (1430328204384534528)]} 0 4
[junit4:junit4] 2> 12885 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[18 (1430328204385583104)]} 0 3
[junit4:junit4] 2> 12914 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10019 (1430328204419137536)]} 0 0
[junit4:junit4] 2> 12915 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[19 (1430328204419137537)]} 0 1
[junit4:junit4] 2> 12919 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10019 (1430328204422283264)]} 0 1
[junit4:junit4] 2> 12919 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1430328204422283265)]} 0 0
[junit4:junit4] 2> 12920 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10019 (1430328204422283264)]} 0 3
[junit4:junit4] 2> 12920 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[19 (1430328204422283265)]} 0 3
[junit4:junit4] 2> 12949 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10013 (-1430328204455837696)]} 0 0
[junit4:junit4] 2> 12949 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[13 (-1430328204455837697)]} 0 0
[junit4:junit4] 2> 12953 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10013 (-1430328204457934848)]} 0 0
[junit4:junit4] 2> 12953 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[13 (-1430328204457934849)]} 0 0
[junit4:junit4] 2> 12954 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10013 (-1430328204457934848)]} 0 3
[junit4:junit4] 2> 12954 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[13 (-1430328204457934849)]} 0 3
[junit4:junit4] 2> 12956 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10020 (1430328204463177728)]} 0 0
[junit4:junit4] 2> 12957 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[20 (1430328204463177729)]} 0 1
[junit4:junit4] 2> 12961 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10020 (1430328204466323456)]} 0 0
[junit4:junit4] 2> 12962 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1430328204466323457)]} 0 1
[junit4:junit4] 2> 12962 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10020 (1430328204466323456)]} 0 3
[junit4:junit4] 2> 12963 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[20 (1430328204466323457)]} 0 4
[junit4:junit4] 2> 13007 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10021 (1430328204516655104)]} 0 0
[junit4:junit4] 2> 13008 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[21 (1430328204516655105)]} 0 1
[junit4:junit4] 2> 13012 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10021 (1430328204519800832)]} 0 0
[junit4:junit4] 2> 13013 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1430328204519800833)]} 0 1
[junit4:junit4] 2> 13013 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10021 (1430328204519800832)]} 0 3
[junit4:junit4] 2> 13013 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[21 (1430328204519800833)]} 0 3
[junit4:junit4] 2> 13107 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[22 (1430328204620464128)]} 0 1
[junit4:junit4] 2> 13107 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10022 (1430328204621512704)]} 0 0
[junit4:junit4] 2> 13111 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1430328204623609856)]} 0 0
[junit4:junit4] 2> 13112 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10022 (1430328204623609857)]} 0 1
[junit4:junit4] 2> 13112 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[22 (1430328204623609856)]} 0 3
[junit4:junit4] 2> 13113 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10022 (1430328204623609857)]} 0 4
[junit4:junit4] 2> 13197 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[23 (1430328204715884544)]} 0 1
[junit4:junit4] 2> 13197 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10023 (1430328204715884545)]} 0 0
[junit4:junit4] 2> 13202 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1430328204717981696)]} 0 1
[junit4:junit4] 2> 13202 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10023 (1430328204717981697)]} 0 1
[junit4:junit4] 2> 13202 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[23 (1430328204717981696)]} 0 3
[junit4:junit4] 2> 13203 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10023 (1430328204717981697)]} 0 4
[junit4:junit4] 2> 13279 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10024 (1430328204801867777)]} 0 0
[junit4:junit4] 2> 13279 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[24 (1430328204801867776)]} 0 0
[junit4:junit4] 2> 13284 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10024 (1430328204805013504)]} 0 0
[junit4:junit4] 2> 13285 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1430328204805013505)]} 0 1
[junit4:junit4] 2> 13285 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10024 (1430328204805013504)]} 0 3
[junit4:junit4] 2> 13285 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[24 (1430328204805013505)]} 0 3
[junit4:junit4] 2> 13310 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10015 (-1430328204834373632)]} 0 0
[junit4:junit4] 2> 13312 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[15 (-1430328204836470784)]} 0 0
[junit4:junit4] 2> 13316 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10015 (-1430328204838567936)]} 0 0
[junit4:junit4] 2> 13316 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[15 (-1430328204839616512)]} 0 0
[junit4:junit4] 2> 13317 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10015 (-1430328204838567936)]} 0 3
[junit4:junit4] 2> 13317 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[15 (-1430328204839616512)]} 0 2
[junit4:junit4] 2> 13319 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10025 (1430328204843810816)]} 0 0
[junit4:junit4] 2> 13320 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[25 (1430328204843810817)]} 0 1
[junit4:junit4] 2> 13324 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10025 (1430328204845907968)]} 0 1
[junit4:junit4] 2> 13324 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1430328204846956544)]} 0 0
[junit4:junit4] 2> 13325 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10025 (1430328204845907968)]} 0 4
[junit4:junit4] 2> 13325 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[25 (1430328204846956544)]} 0 3
[junit4:junit4] 2> 13356 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10016 (-1430328204882608128)]} 0 0
[junit4:junit4] 2> 13356 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[16 (-1430328204882608129)]} 0 0
[junit4:junit4] 2> 13360 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10016 (-1430328204884705280)]} 0 0
[junit4:junit4] 2> 13360 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[16 (-1430328204885753856)]} 0 0
[junit4:junit4] 2> 13361 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10016 (-1430328204884705280)]} 0 3
[junit4:junit4] 2> 13361 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[16 (-1430328204885753856)]} 0 3
[junit4:junit4] 2> 13364 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10026 (1430328204889948160)]} 0 1
[junit4:junit4] 2> 13364 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[26 (1430328204890996736)]} 0 0
[junit4:junit4] 2> 13369 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10026 (1430328204893093888)]} 0 1
[junit4:junit4] 2> 13369 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1430328204893093889)]} 0 1
[junit4:junit4] 2> 13370 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10026 (1430328204893093888)]} 0 4
[junit4:junit4] 2> 13370 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[26 (1430328204893093889)]} 0 4
[junit4:junit4] 2> 13417 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10027 (1430328204946571265)]} 0 0
[junit4:junit4] 2> 13418 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[27 (1430328204946571264)]} 0 1
[junit4:junit4] 2> 13421 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10027 (1430328204948668416)]} 0 0
[junit4:junit4] 2> 13422 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1430328204949716992)]} 0 1
[junit4:junit4] 2> 13422 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10027 (1430328204948668416)]} 0 3
[junit4:junit4] 2> 13422 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[27 (1430328204949716992)]} 0 3
[junit4:junit4] 2> 13464 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[28 (1430328204995854336)]} 0 0
[junit4:junit4] 2> 13464 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10028 (1430328204995854337)]} 0 0
[junit4:junit4] 2> 13468 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10028 (1430328204997951489)]} 0 0
[junit4:junit4] 2> 13468 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1430328204997951488)]} 0 0
[junit4:junit4] 2> 13468 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10028 (1430328204997951489)]} 0 2
[junit4:junit4] 2> 13468 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[28 (1430328204997951488)]} 0 2
[junit4:junit4] 2> 13568 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10029 (1430328205104906240)]} 0 1
[junit4:junit4] 2> 13568 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[29 (1430328205104906241)]} 0 0
[junit4:junit4] 2> 13573 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10029 (1430328205107003392)]} 0 1
[junit4:junit4] 2> 13573 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1430328205107003393)]} 0 1
[junit4:junit4] 2> 13574 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10029 (1430328205107003392)]} 0 4
[junit4:junit4] 2> 13574 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[29 (1430328205107003393)]} 0 4
[junit4:junit4] 2> 13672 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10030 (1430328205212909568)]} 0 1
[junit4:junit4] 2> 13672 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[30 (1430328205212909569)]} 0 1
[junit4:junit4] 2> 13677 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10030 (1430328205216055296)]} 0 1
[junit4:junit4] 2> 13677 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1430328205216055297)]} 0 0
[junit4:junit4] 2> 13678 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10030 (1430328205216055296)]} 0 4
[junit4:junit4] 2> 13678 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[30 (1430328205216055297)]} 0 4
[junit4:junit4] 2> 13712 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10017 (-1430328205255901184)]} 0 0
[junit4:junit4] 2> 13713 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[17 (-1430328205255901185)]} 0 1
[junit4:junit4] 2> 13716 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10017 (-1430328205257998336)]} 0 0
[junit4:junit4] 2> 13717 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[17 (-1430328205259046912)]} 0 1
[junit4:junit4] 2> 13717 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10017 (-1430328205257998336)]} 0 3
[junit4:junit4] 2> 13717 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[17 (-1430328205259046912)]} 0 2
[junit4:junit4] 2> 13720 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10031 (1430328205263241216)]} 0 1
[junit4:junit4] 2> 13720 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[31 (1430328205263241217)]} 0 1
[junit4:junit4] 2> 13725 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10031 (1430328205266386944)]} 0 1
[junit4:junit4] 2> 13725 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1430328205266386945)]} 0 0
[junit4:junit4] 2> 13726 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10031 (1430328205266386944)]} 0 4
[junit4:junit4] 2> 13726 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[31 (1430328205266386945)]} 0 4
[junit4:junit4] 2> 13760 T2619 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 47148
[junit4:junit4] 2> 13761 T2619 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=885743851
[junit4:junit4] 2> 13824 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10032 (1430328205372293120)]} 0 1
[junit4:junit4] 2> 13824 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[32 (1430328205372293121)]} 0 1
[junit4:junit4] 2> 13828 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10032 (1430328205375438848)]} 0 0
[junit4:junit4] 2> 13828 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1430328205375438849)]} 0 0
[junit4:junit4] 2> 13829 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10032 (1430328205375438848)]} 0 3
[junit4:junit4] 2> 13829 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[32 (1430328205375438849)]} 0 3
[junit4:junit4] 2> 13917 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10033 (1430328205469810689)]} 0 1
[junit4:junit4] 2> 13917 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[33 (1430328205469810688)]} 0 1
[junit4:junit4] 2> 13921 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10033 (1430328205472956416)]} 0 0
[junit4:junit4] 2> 13922 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1430328205472956417)]} 0 1
[junit4:junit4] 2> 13922 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10033 (1430328205472956416)]} 0 3
[junit4:junit4] 2> 13922 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[33 (1430328205472956417)]} 0 3
[junit4:junit4] 2> 13942 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10018 (-1430328205497073664)]} 0 0
[junit4:junit4] 2> 13943 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[18 (-1430328205498122240)]} 0 1
[junit4:junit4] 2> 13946 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10018 (-1430328205500219392)]} 0 0
[junit4:junit4] 2> 13946 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[18 (-1430328205500219393)]} 0 0
[junit4:junit4] 2> 13947 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10018 (-1430328205500219392)]} 0 3
[junit4:junit4] 2> 13947 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[18 (-1430328205500219393)]} 0 2
[junit4:junit4] 2> 13950 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10034 (1430328205504413696)]} 0 1
[junit4:junit4] 2> 13950 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[34 (1430328205504413697)]} 0 1
[junit4:junit4] 2> 13954 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10034 (1430328205507559424)]} 0 0
[junit4:junit4] 2> 13955 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1430328205507559425)]} 0 1
[junit4:junit4] 2> 13955 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10034 (1430328205507559424)]} 0 3
[junit4:junit4] 2> 13955 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[34 (1430328205507559425)]} 0 3
[junit4:junit4] 2> 13961 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10021 (-1430328205516996608)]} 0 1
[junit4:junit4] 2> 13961 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[21 (-1430328205516996609)]} 0 0
[junit4:junit4] 2> 13965 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10021 (-1430328205519093760)]} 0 0
[junit4:junit4] 2> 13965 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[21 (-1430328205519093761)]} 0 0
[junit4:junit4] 2> 13965 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10021 (-1430328205519093760)]} 0 2
[junit4:junit4] 2> 13966 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[21 (-1430328205519093761)]} 0 3
[junit4:junit4] 2> 13968 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10035 (1430328205523288064)]} 0 1
[junit4:junit4] 2> 13968 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[35 (1430328205524336640)]} 0 0
[junit4:junit4] 2> 13973 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10035 (1430328205526433792)]} 0 1
[junit4:junit4] 2> 13973 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1430328205526433793)]} 0 1
[junit4:junit4] 2> 13973 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10035 (1430328205526433792)]} 0 3
[junit4:junit4] 2> 13974 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[35 (1430328205526433793)]} 0 4
[junit4:junit4] 2> 13991 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10036 (1430328205547405312)]} 0 1
[junit4:junit4] 2> 13991 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[36 (1430328205547405313)]} 0 1
[junit4:junit4] 2> 13995 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10036 (1430328205550551040)]} 0 0
[junit4:junit4] 2> 13996 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1430328205550551041)]} 0 1
[junit4:junit4] 2> 13996 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10036 (1430328205550551040)]} 0 3
[junit4:junit4] 2> 13996 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[36 (1430328205550551041)]} 0 3
[junit4:junit4] 2> 14062 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10024 (-1430328205622902784)]} 0 1
[junit4:junit4] 2> 14062 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[24 (-1430328205622902785)]} 0 0
[junit4:junit4] 2> 14066 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10024 (-1430328205624999936)]} 0 0
[junit4:junit4] 2> 14066 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[24 (-1430328205624999937)]} 0 0
[junit4:junit4] 2> 14067 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[10024 (-1430328205624999936)]} 0 3
[junit4:junit4] 2> 14067 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[24 (-1430328205624999937)]} 0 3
[junit4:junit4] 2> 14069 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10037 (1430328205630242816)]} 0 0
[junit4:junit4] 2> 14069 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[37 (1430328205630242817)]} 0 0
[junit4:junit4] 2> 14074 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10037 (1430328205633388544)]} 0 0
[junit4:junit4] 2> 14075 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1430328205633388545)]} 0 1
[junit4:junit4] 2> 14075 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10037 (1430328205633388544)]} 0 4
[junit4:junit4] 2> 14075 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[37 (1430328205633388545)]} 0 3
[junit4:junit4] 2> 14112 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14113 T2642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47148_gpx%2Fsq_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:47148_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47148/gpx/sq"}
[junit4:junit4] 2> 14118 T2648 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> 14118 T2677 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> 14118 T2641 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> 14118 T2661 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> 14160 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10038 (1430328205724614656)]} 0 1
[junit4:junit4] 2> 14160 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[38 (1430328205725663232)]} 0 1
[junit4:junit4] 2> 14163 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10038 (1430328205728808960)]} 0 1
[junit4:junit4] 2> 14163 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[38 (1430328205728808961)]} 0 0
[junit4:junit4] 2> 14226 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10039 (1430328205793820672)]} 0 1
[junit4:junit4] 2> 14226 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[39 (1430328205793820673)]} 0 1
[junit4:junit4] 2> 14229 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10039 (1430328205796966400)]} 0 1
[junit4:junit4] 2> 14229 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[39 (1430328205796966401)]} 0 1
[junit4:junit4] 2> 14249 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10029 (-1430328205818986496)]} 0 0
[junit4:junit4] 2> 14250 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[29 (-1430328205820035072)]} 0 0
[junit4:junit4] 2> 14252 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10029 (-1430328205822132224)]} 0 0
[junit4:junit4] 2> 14252 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[29 (-1430328205822132225)]} 0 0
[junit4:junit4] 2> 14255 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10040 (1430328205824229376)]} 0 1
[junit4:junit4] 2> 14255 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[40 (1430328205825277952)]} 0 0
[junit4:junit4] 2> 14257 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10040 (1430328205827375104)]} 0 0
[junit4:junit4] 2> 14257 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[40 (1430328205827375105)]} 0 0
[junit4:junit4] 2> 14320 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10030 (-1430328205893435392)]} 0 0
[junit4:junit4] 2> 14320 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[30 (-1430328205893435393)]} 0 0
[junit4:junit4] 2> 14323 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[30 (-1430328205896581121)]} 0 0
[junit4:junit4] 2> 14323 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10030 (-1430328205896581120)]} 0 0
[junit4:junit4] 2> 14326 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[41 (1430328205898678272)]} 0 1
[junit4:junit4] 2> 14326 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10041 (1430328205898678273)]} 0 1
[junit4:junit4] 2> 14329 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[41 (1430328205901824000)]} 0 1
[junit4:junit4] 2> 14329 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10041 (1430328205901824001)]} 0 1
[junit4:junit4] 2> 14367 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10042 (1430328205941669889)]} 0 1
[junit4:junit4] 2> 14367 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[42 (1430328205941669888)]} 0 1
[junit4:junit4] 2> 14370 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10042 (1430328205944815616)]} 0 1
[junit4:junit4] 2> 14370 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[42 (1430328205945864192)]} 0 0
[junit4:junit4] 2> 14396 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10032 (-1430328205973127169)]} 0 0
[junit4:junit4] 2> 14396 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[32 (-1430328205973127168)]} 0 0
[junit4:junit4] 2> 14399 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[32 (-1430328205976272897)]} 0 1
[junit4:junit4] 2> 14399 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10032 (-1430328205976272896)]} 0 1
[junit4:junit4] 2> 14401 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[43 (1430328205977321472)]} 0 1
[junit4:junit4] 2> 14401 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10043 (1430328205978370048)]} 0 0
[junit4:junit4] 2> 14403 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[43 (1430328205980467200)]} 0 0
[junit4:junit4] 2> 14403 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10043 (1430328205980467201)]} 0 0
[junit4:junit4] 2> 14456 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10044 (1430328206034993153)]} 0 1
[junit4:junit4] 2> 14456 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[44 (1430328206034993152)]} 0 1
[junit4:junit4] 2> 14458 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10044 (1430328206038138880)]} 0 0
[junit4:junit4] 2> 14459 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[44 (1430328206038138881)]} 0 1
[junit4:junit4] 2> 14522 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10045 (1430328206105247744)]} 0 0
[junit4:junit4] 2> 14523 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[45 (1430328206105247745)]} 0 1
[junit4:junit4] 2> 14525 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10045 (1430328206108393472)]} 0 0
[junit4:junit4] 2> 14525 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[45 (1430328206108393473)]} 0 0
[junit4:junit4] 2> 14547 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[36 (-1430328206131462145)]} 0 1
[junit4:junit4] 2> 14547 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10036 (-1430328206131462144)]} 0 1
[junit4:junit4] 2> 14549 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[10036 (-1430328206133559296)]} 0 0
[junit4:junit4] 2> 14549 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[36 (-1430328206133559297)]} 0 0
[junit4:junit4] 2> 14552 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10046 (1430328206135656448)]} 0 1
[junit4:junit4] 2> 14552 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[46 (1430328206135656449)]} 0 1
[junit4:junit4] 2> 14554 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10046 (1430328206138802176)]} 0 0
[junit4:junit4] 2> 14554 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[46 (1430328206138802177)]} 0 0
[junit4:junit4] 2> 14573 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10047 (1430328206158725120)]} 0 0
[junit4:junit4] 2> 14573 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[47 (1430328206158725121)]} 0 0
[junit4:junit4] 2> 14575 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10047 (1430328206160822272)]} 0 0
[junit4:junit4] 2> 14575 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[47 (1430328206160822273)]} 0 0
[junit4:junit4] 2> 14641 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[41 (-1430328206230028289)]} 0 0
[junit4:junit4] 2> 14641 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10041 (-1430328206230028288)]} 0 0
[junit4:junit4] 2> 14644 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[41 (-1430328206232125440)]} 0 1
[junit4:junit4] 2> 14644 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10041 (-1430328206232125441)]} 0 1
[junit4:junit4] 2> 14646 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10048 (1430328206234222593)]} 0 1
[junit4:junit4] 2> 14646 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[48 (1430328206234222592)]} 0 1
[junit4:junit4] 2> 14648 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[48 (1430328206236319744)]} 0 1
[junit4:junit4] 2> 14648 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10048 (1430328206237368320)]} 0 1
[junit4:junit4] 2> 14725 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[49 (1430328206318108672)]} 0 0
[junit4:junit4] 2> 14725 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10049 (1430328206318108673)]} 0 0
[junit4:junit4] 2> 14728 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[49 (1430328206320205824)]} 0 1
[junit4:junit4] 2> 14728 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10049 (1430328206320205825)]} 0 1
[junit4:junit4] 2> C395_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:47148_gpx%2Fsq, base_url=http://127.0.0.1:47148/gpx/sq}
[junit4:junit4] 2> 14760 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52822/gpx/sq/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 14760 T2680 C395 P47148 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47148/gpx/sq START replicas=[http://127.0.0.1:52822/gpx/sq/collection1/] nUpdates=100
[junit4:junit4] 2> 14760 T2680 C395 P47148 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 14761 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 14761 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 14761 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 14762 T2680 C395 P47148 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/tlog/tlog.0000000000000000000 refcount=1}}
[junit4:junit4] 2> 14762 T2680 C395 P47148 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52822/gpx/sq/collection1/. core=collection1
[junit4:junit4] 2> 14762 T2680 C395 P47148 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14762 T2656 C397 P52822 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 14764 T2657 C397 P52822 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14769 T2657 C397 P52822 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7dca5810 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63c882b5; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7dca5810 lockFactory=org.apache.lucene.store.NativeFSLockFactory@63c882b5; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875)),segFN=segments_2,generation=2,filenames=[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_Pulsing41_0.tim, _0_MockFixedIntBlock_0.tii, _0_MockFixedIntBlock_0.doc, _0_Pulsing41_0.tip, _0.nvd, segments_2, _0.fdx, _0.si, _0.fdt]
[junit4:junit4] 2> 14770 T2657 C397 P52822 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_Pulsing41_0.tim, _0_MockFixedIntBlock_0.tii, _0_MockFixedIntBlock_0.doc, _0_Pulsing41_0.tip, _0.nvd, segments_2, _0.fdx, _0.si, _0.fdt]
[junit4:junit4] 2> 14771 T2657 C397 P52822 oass.SolrIndexSearcher.<init> Opening Searcher@2b314986 realtime
[junit4:junit4] 2> 14771 T2657 C397 P52822 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 14772 T2657 C397 P52822 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 14772 T2680 C395 P47148 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14772 T2680 C395 P47148 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 14774 T2655 C397 P52822 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 14774 T2655 C397 P52822 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 14775 T2680 C395 P47148 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 14775 T2680 C395 P47148 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 14775 T2680 C395 P47148 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 14776 T2656 C397 P52822 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 14777 T2680 C395 P47148 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 24
[junit4:junit4] 2> 14778 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10044 (-1430328206373683201)]} 0 0
[junit4:junit4] 2> 14778 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[44 (-1430328206373683200)]} 0 0
[junit4:junit4] 2> 14778 T2680 C395 P47148 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index.20130323093434449
[junit4:junit4] 2> 14778 T2680 C395 P47148 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042)) fullCopy=true
[junit4:junit4] 2> 14780 T2655 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.tib&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14780 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[44 (-1430328206375780353)]} 0 0
[junit4:junit4] 2> 14780 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10044 (-1430328206375780352)]} 0 0
[junit4:junit4] 2> 14783 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[50 (1430328206377877504)]} 0 1
[junit4:junit4] 2> 14783 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10050 (1430328206377877505)]} 0 1
[junit4:junit4] 2> 14784 T2656 C397 P52822 REQ /replication {file=_0_NestedPulsing_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14785 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[50 (1430328206379974656)]} 0 1
[junit4:junit4] 2> 14785 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10050 (1430328206381023232)]} 0 1
[junit4:junit4] 2> 14787 T2655 C397 P52822 REQ /replication {file=_0_NestedPulsing_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14790 T2656 C397 P52822 REQ /replication {file=_0_NestedPulsing_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14793 T2654 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.pyl&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14793 T2680 C395 P47148 oash.SnapPuller$DirectoryFileFetcher.fetchPackets WARNING No content recieved for file: {name=_0_MockFixedIntBlock_0.pyl, size=0}
[junit4:junit4] 2> 14795 T2657 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.skp&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14799 T2655 C397 P52822 REQ /replication {file=_0_Pulsing41_0.tim&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14802 T2656 C397 P52822 REQ /replication {file=_0_Pulsing41_0.tip&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14805 T2654 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.tii&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14819 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10045 (-1430328206416674816)]} 0 0
[junit4:junit4] 2> 14819 T2657 C397 P52822 REQ /replication {file=_0.nvd&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14819 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[45 (-1430328206416674817)]} 0 0
[junit4:junit4] 2> 14821 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10045 (-1430328206418771968)]} 0 0
[junit4:junit4] 2> 14821 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[45 (-1430328206418771969)]} 0 0
[junit4:junit4] 2> 14822 T2654 C397 P52822 REQ /replication {file=_0.si&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14823 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10051 (1430328206420869121)]} 0 0
[junit4:junit4] 2> 14823 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[51 (1430328206420869120)]} 0 0
[junit4:junit4] 2> 14825 T2657 C397 P52822 REQ /replication {file=_0_NestedPulsing_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14825 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10051 (1430328206422966272)]} 0 0
[junit4:junit4] 2> 14825 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[51 (1430328206422966273)]} 0 0
[junit4:junit4] 2> 14828 T2654 C397 P52822 REQ /replication {file=_0.fnm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14830 T2657 C397 P52822 REQ /replication {file=_0_Memory_0.ram&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14833 T2655 C397 P52822 REQ /replication {file=_0_1.del&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14836 T2656 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14839 T2654 C397 P52822 REQ /replication {file=_0.nvm&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14842 T2657 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.frq&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 14844 T2655 C397 P52822 REQ /replication {file=_0_Pulsing41_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14847 T2656 C397 P52822 REQ /replication {file=_0_Pulsing41_0.pos&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14850 T2654 C397 P52822 REQ /replication {file=_0_MockFixedIntBlock_0.doc&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14852 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10047 (-1430328206451277824)]} 0 0
[junit4:junit4] 2> 14852 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[47 (-1430328206451277825)]} 0 0
[junit4:junit4] 2> 14853 T2657 C397 P52822 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14854 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10047 (-1430328206453374976)]} 0 0
[junit4:junit4] 2> 14854 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[47 (-1430328206453374977)]} 0 0
[junit4:junit4] 2> 14855 T2654 C397 P52822 REQ /replication {file=_0.fdx&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14856 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10052 (1430328206455472129)]} 0 0
[junit4:junit4] 2> 14856 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[52 (1430328206455472128)]} 0 1
[junit4:junit4] 2> 14858 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10052 (1430328206457569280)]} 0 0
[junit4:junit4] 2> 14858 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[52 (1430328206457569281)]} 0 0
[junit4:junit4] 2> 14858 T2656 C397 P52822 REQ /replication {file=_0.fdt&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 14859 T2680 C395 P47148 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 14860 T2680 C395 P47148 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130323093434449
[junit4:junit4] 2> 14860 T2680 C395 P47148 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 14861 T2680 C395 P47148 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 14861 T2680 C395 P47148 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 14861 T2680 C395 P47148 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index/ new=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index.20130323093434449
[junit4:junit4] 2> 14864 T2680 C395 P47148 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042)),segFN=segments_2,generation=2,filenames=[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_MockFixedIntBlock_0.doc, _0_MockFixedIntBlock_0.tii, _0.nvd, segments_2, _0.fdx, _0.si, _0.fdt]
[junit4:junit4] 2> 14864 T2680 C395 P47148 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_MockFixedIntBlock_0.doc, _0_MockFixedIntBlock_0.tii, _0.nvd, segments_2, _0.fdx, _0.si, _0.fdt]
[junit4:junit4] 2> 14864 T2680 C395 P47148 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 14866 T2680 C395 P47148 oass.SolrIndexSearcher.<init> Opening Searcher@35dac0a2 main
[junit4:junit4] 2> 14867 T2679 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35dac0a2 main{StandardDirectoryReader(segments_2:3:nrt _0(4.3):C98/38)}
[junit4:junit4] 2> 14868 T2680 C395 P47148 oash.SnapPuller$2.preClose removing old index files MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@927d2b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@472c61b6; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875))
[junit4:junit4] 2> 14868 T2680 C395 P47148 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/index
[junit4:junit4] 2> 14868 T2680 C395 P47148 oash.SnapPuller$2.postClose removing old index directory MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@927d2b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@472c61b6; maxCacheMB=0.5927734375 maxMergeSizeMB=0.326171875))
[junit4:junit4] 2> 14868 T2680 C395 P47148 oasc.RecoveryStrategy.replay Replaying buffered documents. core=collection1
[junit4:junit4] 2> 14868 T2688 C395 P47148 oasu.UpdateLog$LogReplayer.doReplay WARNING Starting log replay tlog{file=./org.apache.solr.cloud.RecoveryZkTest-1364067259676/jetty2/tlog/tlog.0000000000000000000 refcount=2} active=true starting pos=5397
[junit4:junit4] 2> 14868 T2688 C395 P47148 oasu.DirectUpdateHandler2.commit start commit{flags=2,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 14870 T2688 C395 P47148 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042)),segFN=segments_2,generation=2,filenames=[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_MockFixedIntBlock_0.doc, _0_MockFixedIntBlock_0.tii, _0.nvd, segments_2, _0.fdx, _0.si, _0.fdt]
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042)),segFN=segments_3,generation=3,filenames=[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_MockFixedIntBlock_0.doc, _0_MockFixedIntBlock_0.tii, _0.nvd, _0.fdx, _0.si, _0.fdt, segments_3]
[junit4:junit4] 2> 14871 T2688 C395 P47148 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_MockFixedIntBlock_0.doc, _0_MockFixedIntBlock_0.tii, _0.nvd, _0.fdx, _0.si, _0.fdt, segments_3]
[junit4:junit4] 2> 14871 T2688 C395 P47148 oass.SolrIndexSearcher.<init> Opening Searcher@591efc5c main
[junit4:junit4] 2> 14872 T2688 C395 P47148 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 14872 T2679 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@591efc5c main{StandardDirectoryReader(segments_2:3:nrt _0(4.3):C98/38)}
[junit4:junit4] 2> 14872 T2688 C395 P47148 [collection1] {} 0 4
[junit4:junit4] 2> 14872 T2688 C395 P47148 oasu.UpdateLog$LogReplayer.run WARNING Log replay finished. recoveryInfo=RecoveryInfo{adds=0 deletes=0 deleteByQuery=0 errors=0 positionOfStart=5397}
[junit4:junit4] 2> 14873 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 14873 T2680 C395 P47148 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 14873 T2680 C395 P47148 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14874 T2680 C395 P47148 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 14897 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10053 (1430328206498463744)]} 0 0
[junit4:junit4] 2> 14897 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[53 (1430328206498463745)]} 0 0
[junit4:junit4] 2> 14900 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10053 (1430328206500560896)]} 0 1
[junit4:junit4] 2> 14900 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[53 (1430328206500560897)]} 0 1
[junit4:junit4] 2> 14912 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10054 (1430328206514192384)]} 0 0
[junit4:junit4] 2> 14912 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[54 (1430328206514192385)]} 0 0
[junit4:junit4] 2> 14914 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10054 (1430328206516289536)]} 0 0
[junit4:junit4] 2> 14914 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[54 (1430328206516289537)]} 0 0
[junit4:junit4] 2> 14929 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[49 (-1430328206532018177)]} 0 0
[junit4:junit4] 2> 14929 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10049 (-1430328206532018176)]} 0 0
[junit4:junit4] 2> 14931 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10049 (-1430328206534115328)]} 0 0
[junit4:junit4] 2> 14931 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[49 (-1430328206534115329)]} 0 0
[junit4:junit4] 2> 14933 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10055 (1430328206536212480)]} 0 0
[junit4:junit4] 2> 14933 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[55 (1430328206536212481)]} 0 0
[junit4:junit4] 2> 14935 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[55 (1430328206538309632)]} 0 0
[junit4:junit4] 2> 14935 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10055 (1430328206538309633)]} 0 0
[junit4:junit4] 2> 15037 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[56 (1430328206645264384)]} 0 1
[junit4:junit4] 2> 15037 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10056 (1430328206645264385)]} 0 1
[junit4:junit4] 2> 15039 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10056 (1430328206647361536)]} 0 0
[junit4:junit4] 2> 15039 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[56 (1430328206647361537)]} 0 0
[junit4:junit4] 2> 15062 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[57 (1430328206670430209)]} 0 1
[junit4:junit4] 2> 15062 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10057 (1430328206670430208)]} 0 1
[junit4:junit4] 2> 15064 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[57 (1430328206673575936)]} 0 0
[junit4:junit4] 2> 15064 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10057 (1430328206673575937)]} 0 0
[junit4:junit4] 2> 15147 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[50 (-1430328206760607745)]} 0 0
[junit4:junit4] 2> 15147 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10050 (-1430328206760607744)]} 0 0
[junit4:junit4] 2> 15149 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10050 (-1430328206762704896)]} 0 0
[junit4:junit4] 2> 15149 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[50 (-1430328206762704897)]} 0 0
[junit4:junit4] 2> 15151 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10058 (1430328206764802048)]} 0 0
[junit4:junit4] 2> 15151 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[58 (1430328206764802049)]} 0 0
[junit4:junit4] 2> 15153 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10058 (1430328206766899200)]} 0 0
[junit4:junit4] 2> 15153 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[58 (1430328206766899201)]} 0 0
[junit4:junit4] 2> 15232 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[59 (1430328206848688128)]} 0 1
[junit4:junit4] 2> 15232 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10059 (1430328206848688129)]} 0 1
[junit4:junit4] 2> 15234 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10059 (1430328206851833856)]} 0 0
[junit4:junit4] 2> 15234 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[59 (1430328206851833857)]} 0 0
[junit4:junit4] 2> 15302 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10056 (-1430328206923137024)]} 0 0
[junit4:junit4] 2> 15302 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[56 (-1430328206923137025)]} 0 0
[junit4:junit4] 2> 15304 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[56 (-1430328206925234176)]} 0 0
[junit4:junit4] 2> 15304 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10056 (-1430328206925234177)]} 0 0
[junit4:junit4] 2> 15306 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[60 (1430328206927331328)]} 0 0
[junit4:junit4] 2> 15306 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10060 (1430328206927331329)]} 0 0
[junit4:junit4] 2> 15308 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[60 (1430328206929428480)]} 0 0
[junit4:junit4] 2> 15308 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10060 (1430328206929428481)]} 0 0
[junit4:junit4] 2> 15311 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[60 (-1430328206932574208)]} 0 0
[junit4:junit4] 2> 15311 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10060 (-1430328206932574209)]} 0 0
[junit4:junit4] 2> 15313 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[60 (-1430328206934671360)]} 0 1
[junit4:junit4] 2> 15313 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10060 (-1430328206934671361)]} 0 0
[junit4:junit4] 2> 15314 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[61 (1430328206935719936)]} 0 0
[junit4:junit4] 2> 15315 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10061 (1430328206935719937)]} 0 1
[junit4:junit4] 2> 15316 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[61 (1430328206937817088)]} 0 0
[junit4:junit4] 2> 15317 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10061 (1430328206937817089)]} 0 1
[junit4:junit4] 2> 15408 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10062 (1430328207033237504)]} 0 1
[junit4:junit4] 2> 15408 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[62 (1430328207033237505)]} 0 1
[junit4:junit4] 2> 15411 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10062 (1430328207036383232)]} 0 1
[junit4:junit4] 2> 15411 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[62 (1430328207037431808)]} 0 1
[junit4:junit4] 2> 15481 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10063 (1430328207110832128)]} 0 1
[junit4:junit4] 2> 15482 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[63 (1430328207110832129)]} 0 1
[junit4:junit4] 2> 15483 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10063 (1430328207112929280)]} 0 0
[junit4:junit4] 2> 15484 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[63 (1430328207112929281)]} 0 1
[junit4:junit4] 2> 15558 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10061 (-1430328207190523904)]} 0 1
[junit4:junit4] 2> 15558 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[61 (-1430328207191572480)]} 0 0
[junit4:junit4] 2> 15560 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[61 (-1430328207193669632)]} 0 0
[junit4:junit4] 2> 15560 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10061 (-1430328207193669633)]} 0 0
[junit4:junit4] 2> 15562 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[64 (1430328207194718208)]} 0 1
[junit4:junit4] 2> 15562 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10064 (1430328207195766784)]} 0 0
[junit4:junit4] 2> 15564 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[64 (1430328207197863937)]} 0 0
[junit4:junit4] 2> 15564 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10064 (1430328207197863936)]} 0 0
[junit4:junit4] 2> 15622 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15623 T2642 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47148_gpx%2Fsq_collection1",
[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:47148_gpx%2Fsq",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47148/gpx/sq"}
[junit4:junit4] 2> 15636 T2661 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> 15636 T2677 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> 15636 T2641 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> 15636 T2648 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> 15648 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[62 (-1430328207285944320)]} 0 0
[junit4:junit4] 2> 15648 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10062 (-1430328207285944321)]} 0 0
[junit4:junit4] 2> C395_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47148_gpx%2Fsq, base_url=http://127.0.0.1:47148/gpx/sq}
[junit4:junit4] 2> 15652 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[62 (-1430328207288041473)]} 0 1
[junit4:junit4] 2> 15652 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10062 (-1430328207288041472)]} 0 1
[junit4:junit4] 2> 15652 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[62 (-1430328207288041473)]} 0 2
[junit4:junit4] 2> 15652 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10062 (-1430328207288041472)]} 0 2
[junit4:junit4] 2> 15655 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[65 (1430328207292235776)]} 0 1
[junit4:junit4] 2> 15656 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10065 (1430328207292235777)]} 0 2
[junit4:junit4] 2> 15660 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1430328207296430081)]} 0 1
[junit4:junit4] 2> 15660 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10065 (1430328207296430080)]} 0 1
[junit4:junit4] 2> 15661 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[65 (1430328207296430081)]} 0 4
[junit4:junit4] 2> 15661 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10065 (1430328207296430080)]} 0 4
[junit4:junit4] 2> 15696 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[64 (-1430328207336275968)]} 0 0
[junit4:junit4] 2> 15696 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10064 (-1430328207336275969)]} 0 0
[junit4:junit4] 2> 15699 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[10064 (-1430328207338373121)]} 0 0
[junit4:junit4] 2> 15699 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {delete=[64 (-1430328207338373120)]} 0 0
[junit4:junit4] 2> 15700 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10064 (-1430328207338373121)]} 0 2
[junit4:junit4] 2> 15700 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[64 (-1430328207338373120)]} 0 2
[junit4:junit4] 2> 15702 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10066 (1430328207341518848)]} 0 1
[junit4:junit4] 2> 15702 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[66 (1430328207342567424)]} 0 0
[junit4:junit4] 2> 15705 T2671 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10066 (1430328207343616000)]} 0 0
[junit4:junit4] 2> 15706 T2673 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1430328207344664576)]} 0 1
[junit4:junit4] 2> 15706 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10066 (1430328207343616000)]} 0 3
[junit4:junit4] 2> 15706 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[66 (1430328207344664576)]} 0 2
[junit4:junit4] 2> 15763 T2619 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15764 T2619 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15777 T2619 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@333b25ba
[junit4:junit4] 2> 15791 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10067 (1430328207435890688)]} 0 0
[junit4:junit4] 2> 15791 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[67 (1430328207435890689)]} 0 0
[junit4:junit4] 2> 15794 T2619 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=52,cumulative_deletesById=24,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 15795 T2619 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 15795 T2619 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 15796 T2672 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10067 (1430328207437987840)]} 0 1
[junit4:junit4] 2> 15796 T2670 C395 P47148 /update {distrib.from=http://127.0.0.1:52822/gpx/sq/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1430328207439036416)]} 0 1
[junit4:junit4] 2> 15796 T2619 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 15796 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10067 (1430328207437987840)]} 0 3
[junit4:junit4] 2> 15796 T2670 C395 P47148 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@333b25ba
[junit4:junit4] 2> 15797 T2670 C395 P47148 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=2,adds=6,deletesById=4,deletesByQuery=0,errors=0,cumulative_adds=54,cumulative_deletesById=24,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 15826 T2619 C395 P47148 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042)),segFN=segments_3,generation=3,filenames=[_0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0_1.del, _0_MockFixedIntBlock_0.pos, _0.nvm, _0_NestedPulsing_0.tip, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tim, _0_MockFixedIntBlock_0.frq, _0_NestedPulsing_0.pos, _0_Pulsing41_0.pos, _0_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.skp, _0_Pulsing41_0.tim, _0_Pulsing41_0.tip, _0_MockFixedIntBlock_0.doc, _0_MockFixedIntBlock_0.tii, _0.nvd, _0.fdx, _0.si, _0.fdt, segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042)),segFN=segments_4,generation=4,filenames=[_1_NestedPulsing_0.tip, _1_MockFixedIntBlock_0.doc, _1_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tip, _1.fnm, _0_NestedPulsing_0.tim, _1_NestedPulsing_0.doc, _0_NestedPulsing_0.pos, _1_Memory_0.ram, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_Pulsing41_0.tim, _0_MockFixedIntBlock_0.tii, _0_Pulsing41_0.tip, _0.nvd, _1_NestedPulsing_0.tim, _0.si, _0_NestedPulsing_0.doc, _1_MockFixedIntBlock_0.tii, _1.nvm, _0.fnm, _1_MockFixedIntBlock_0.frq, _0_Memory_0.ram, _1.nvd, _1_NestedPulsing_0.pos, _0_1.del, _1_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pos, _0.nvm, _1_Pulsing41_0.pos, _0_MockFixedIntBlock_0.frq, _1.fdx, _0_Pulsing41_0.doc, _0_Pulsing41_0.pos, _1_Pulsing41_0.tip, _1_MockFixedIntBlock_0.skp, _1.fdt, _1_Pulsing41_0.tim, _0_MockFixedIntBlock_0.doc, _1.si, _1_MockFixedIntBlock_0.tib, _0.fdx, _1_MockFixedIntBlock_0.pos, _0.fdt, segments_4]
[junit4:junit4] 2> 15827 T2619 C395 P47148 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_1_NestedPulsing_0.tip, _1_MockFixedIntBlock_0.doc, _1_MockFixedIntBlock_0.pyl, _0_MockFixedIntBlock_0.tib, _0_NestedPulsing_0.tip, _1.fnm, _0_NestedPulsing_0.tim, _1_NestedPulsing_0.doc, _0_NestedPulsing_0.pos, _1_Memory_0.ram, _0_MockFixedIntBlock_0.skp, _0_MockFixedIntBlock_0.pyl, _0_Pulsing41_0.tim, _0_MockFixedIntBlock_0.tii, _0_Pulsing41_0.tip, _0.nvd, _1_NestedPulsing_0.tim, _0.si, _0_NestedPulsing_0.doc, _1_MockFixedIntBlock_0.tii, _1.nvm, _0.fnm, _1_MockFixedIntBlock_0.frq, _0_Memory_0.ram, _1.nvd, _1_NestedPulsing_0.pos, _0_1.del, _1_Pulsing41_0.doc, _0_MockFixedIntBlock_0.pos, _0.nvm, _1_Pulsing41_0.pos, _0_MockFixedIntBlock_0.frq, _1.fdx, _0_Pulsing41_0.doc, _0_Pulsing41_0.pos, _1_Pulsing41_0.tip, _1_MockFixedIntBlock_0.skp, _1.fdt, _1_Pulsing41_0.tim, _0_MockFixedIntBlock_0.doc, _1.si, _1_MockFixedIntBlock_0.tib, _0.fdx, _1_MockFixedIntBlock_0.pos, _0.fdt, segments_4]
[junit4:junit4] 2> 15828 T2670 C395 P47148 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 15828 T2619 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 15829 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[67 (1430328207439036416)]} 0 36
[junit4:junit4] 2> 15829 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0008
[junit4:junit4] 2> 15832 T2648 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> 15832 T2677 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> 15832 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44348 which had sessionid 0x13d98be951f0008
[junit4:junit4] 2> 15832 T2677 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 15832 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0008 closed
[junit4:junit4] 2> 15832 T2677 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 15833 T2661 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15833 T2641 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15833 T2677 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 15833 T2661 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> 15833 T2641 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> 15844 T2648 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 15855 T2619 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/gpx/sq,null}
[junit4:junit4] 2> 15885 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10068 (1430328207533408256)]} 0 1
[junit4:junit4] 2> 15887 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10068 (1430328207536553984)]} 0 0
[junit4:junit4] 2> 15918 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[68 (1430328207568011264)]} 0 1
[junit4:junit4] 2> 15921 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[68 (1430328207571156992)]} 0 1
[junit4:junit4] 2> 15945 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[10067 (-1430328207597371392)]} 0 0
[junit4:junit4] 2> 15948 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[10067 (-1430328207600517120)]} 0 0
[junit4:junit4] 2> 15950 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[10069 (1430328207602614272)]} 0 0
[junit4:junit4] 2> 15953 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[10069 (1430328207604711424)]} 0 1
[junit4:junit4] 2> 15979 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[67 (-1430328207633022976)]} 0 0
[junit4:junit4] 2> 15982 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[67 (-1430328207636168704)]} 0 1
[junit4:junit4] 2> 15984 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[69 (1430328207638265856)]} 0 0
[junit4:junit4] 2> 15987 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[69 (1430328207640363008)]} 0 1
[junit4:junit4] 2> 16049 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10070 (1430328207705374720)]} 0 1
[junit4:junit4] 2> 16051 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10070 (1430328207708520448)]} 0 0
[junit4:junit4] 2> 16082 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[70 (1430328207741026304)]} 0 0
[junit4:junit4] 2> 16085 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[70 (1430328207744172032)]} 0 0
[junit4:junit4] 2> 16108 T2619 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 16111 T2619 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47148
[junit4:junit4] 2> 16112 T2619 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 16113 T2619 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 16114 T2619 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784
[junit4:junit4] 2> 16114 T2619 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/solr.xml
[junit4:junit4] 2> 16115 T2619 oasc.CoreContainer.<init> New CoreContainer 187234981
[junit4:junit4] 2> 16115 T2619 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/'
[junit4:junit4] 2> 16116 T2619 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1364067267784/'
[junit4:junit4] 2> 16140 T2637 C396 P48820 /update {wt=javabin&version=2} {delete=[10068 (-1430328207801843712)]} 0 1
[junit4:junit4] 2> 16141 T2619 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 16141 T2619 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 16142 T2656 C397 P52822 /update {wt=javabin&version=2} {delete=[10068 (-1430328207803940864)]} 0 0
[junit4:junit4] 2> 16142 T2619 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 16142 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 16142 T2619 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 16143 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 16143 T2619 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 16143 T2619 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 16144 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10071 (1430328207804989440)]} 0 1
[junit4:junit4] 2> 16144 T2619 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 16144 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 16146 T2655 C397 P52822 /update {wt=javabin&version=2} {add=[10071 (1430328207807086592)]} 0 1
[junit4:junit4] 2> 16150 T2619 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 16159 T2619 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:38691/solr
[junit4:junit4] 2> 16159 T2619 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 16160 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@21c32450
[junit4:junit4] 2> 16160 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16161 T2698 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 16161 T2698 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 16161 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44370
[junit4:junit4] 2> 16162 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44370
[junit4:junit4] 2> 16162 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f0009 with negotiated timeout 20000 for client /127.0.0.1:44370
[junit4:junit4] 2> 16162 T2698 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f0009, negotiated timeout = 20000
[junit4:junit4] 2> 16163 T2699 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21c32450 name:ZooKeeperConnection Watcher:127.0.0.1:38691 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16163 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16164 T2624 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98be951f0009
[junit4:junit4] 2> 16164 T2699 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 16164 T2621 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:44370 which had sessionid 0x13d98be951f0009
[junit4:junit4] 2> 16164 T2619 oaz.ZooKeeper.close Session: 0x13d98be951f0009 closed
[junit4:junit4] 2> 16165 T2619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 16168 T2619 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:38691/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1c63a27f
[junit4:junit4] 2> 16169 T2619 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16170 T2700 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:38691. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 16171 T2700 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:38691, initiating session
[junit4:junit4] 2> 16171 T2621 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:44371
[junit4:junit4] 2> 16171 T2621 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:44371
[junit4:junit4] 2> 16172 T2623 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98be951f000a with negotiated timeout 20000 for client /127.0.0.1:44371
[junit4:junit4] 2> 16172 T2700 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:38691, sessionid = 0x13d98be951f000a, negotiated timeout = 20000
[junit4:junit4] 2> 16172 T2701 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c63a27f name:ZooKeeperConnection Watcher:127.0.0.1:38691/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16173 T2619 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16174 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f000a type:create cxid:0x1 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16174 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[68 (-1430328207837495296)]} 0 0
[junit4:junit4] 2> 16175 T2624 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98be951f000a type:create cxid:0x3 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16176 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[68 (-1430328207839592448)]} 0 0
[junit4:junit4] 2> 16177 T2619 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 16178 T2636 C396 P48820 /update {wt=javabin&version=2} {add=[71 (1430328207841689600)]} 0 0
[junit4:junit4] 2> 16180 T2657 C397 P52822 /update {wt=javabin&version=2} {add=[71 (1430328207843786752)]} 0 0
[junit4:junit4] 2> 16195 T2634 C396 P48820 /update {wt=javabin&version=2} {add=[10072 (1430328207858466816)]} 0 1
[junit4:junit4] 2> 16197 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10072 (1430328207860563968)]} 0 1
[junit4:junit4] 2> 16229 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[72 (1430328207895166976)]} 0 0
[junit4:junit4] 2> 16231 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[72 (1430328207897264128)]} 0 0
[junit4:junit4] 2> 16247 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[10070 (-1430328207914041344)]} 0 0
[junit4:junit4] 2> 16249 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[10070 (-1430328207916138496)]} 0 0
[junit4:junit4] 2> 16251 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[10073 (1430328207918235648)]} 0 0
[junit4:junit4] 2> 16253 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[10073 (1430328207920332800)]} 0 0
[junit4:junit4] 2> 16262 T2634 C396 P48820 /update {wt=javabin&version=2} {delete=[10071 (-1430328207929769984)]} 0 0
[junit4:junit4] 2> 16264 T2655 C397 P52822 /update {wt=javabin&version=2} {delete=[10071 (-1430328207931867136)]} 0 0
[junit4:junit4] 2> 16266 T2635 C396 P48820 /update {wt=javabin&version=2} {add=[10074 (1430328207932915712)]} 0 1
[junit4:junit4] 2> 16268 T2654 C397 P52822 /update {wt=javabin&version=2} {add=[10074 (1430328207935012864)]} 0 1
[junit4:junit4] 2> 16282 T2636 C396 P48820 /update {wt=javabin&version=2} {delete=[70 (-1430328207950741504)]} 0 0
[junit4:junit4] 2> 16284 T2657 C397 P52822 /update {wt=javabin&version=2} {delete=[70 (-1430328207952838656)]} 0 0
[junit4:junit4] 2> 16286 T2637 C396 P48820 /update {wt=javabin&version=2} {add=[73 (1430328207954935808)]} 0 0
[junit4:junit4] 2> 16288 T2656 C397 P52822 /update {wt=javabin&version=2} {add=[73 (1430328207957032960)]} 0 0
[junit4:junit4] 2> 16297 T2635 C396 P48820 /update {wt=javabin&version=2} {delete=[71 (-1430328207966470144)]} 0 0
[junit4:junit4] 2> 16298 T2654 C397 P52822 /update {wt=javabin&version=2} {delete=[71 (-1430328207967518720)]} 0 0
[junit4:junit4] 2> 16300 T2636 C396 P48820 /update {wt=javabin&version=
[...truncated too long message...]
ry doPackFST= true)}, docValues:{}, sim=DefaultSimilarity, locale=ar_SY, timezone=Pacific/Tahiti
[junit4:junit4] 2> NOTE: Linux 3.2.0-39-generic amd64/Sun Microsystems Inc. 1.6.0_41 (64-bit)/cpus=8,threads=1,free=11939928,total=196943872
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrIndexConfigTest, SimplePostToolTest, CurrencyFieldXmlFileTest, TestUpdate, TestFastOutputStream, TestPropInject, TestStressReorder, TestDefaultSimilarityFactory, TestJmxMonitoredMap, TestMergePolicyConfig, SampleTest, IndexSchemaRuntimeFieldTest, CoreContainerCoreInitFailuresTest, NoCacheHeaderTest, SolrCoreCheckLockOnStartupTest, TestCodecSupport, TestBinaryResponseWriter, URLClassifyProcessorTest, TestElisionMultitermQuery, SpellPossibilityIteratorTest, TestCSVLoader, DistanceFunctionTest, TestBinaryField, OpenCloseCoreStressTest, TestIndexSearcher, TestShardHandlerFactory, TestFoldingMultitermQuery, TestJmxIntegration, TestHashPartitioner, PathHierarchyTokenizerFactoryTest, TestCSVResponseWriter, TestRecovery, SuggesterTSTTest, BasicDistributedZk2Test, TestMultiCoreConfBootstrap, BadIndexSchemaTest, ShardRoutingCustomTest, TestDynamicFieldCollectionResource, TestReload, TestRangeQuery, IndexBasedSpellCheckerTest, StandardRequestHandlerTest, CollectionsAPIDistributedZkTest, DirectSolrSpellCheckerTest, HighlighterTest, TestLazyCores, TestZkChroot, TestFiltering, SolrCmdDistributorTest, TestAnalyzedSuggestions, DOMUtilTest, NumericFieldsTest, TestSystemIdResolver, CurrencyFieldOpenExchangeTest, TestSolrJ, PingRequestHandlerTest, ConvertedLegacyTest, TimeZoneUtilsTest, HighlighterConfigTest, RequiredFieldsTest, DocumentAnalysisRequestHandlerTest, XsltUpdateRequestHandlerTest, TestRandomFaceting, ChaosMonkeySafeLeaderTest, BasicZkTest, RecoveryZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.seed=17F3B233ABDA66C7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_SY -Dtests.timezone=Pacific/Tahiti -Dtests.file.encoding=US-ASCII
[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=2678, name=coreLoadExecutor-2162-thread-1, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1479)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:525)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:329)
[junit4:junit4] > at org.apache.solr.core.SolrCore.getNewIndexDir(SolrCore.java:244)
[junit4:junit4] > at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:458)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:746)
[junit4:junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:619)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.createFromZk(CoreContainer.java:872)
[junit4:junit4] > at org.apache.solr.core.CoreContainer.create(CoreContainer.java:955)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:579)
[junit4:junit4] > at org.apache.solr.core.CoreContainer$2.call(CoreContainer.java:574)
[junit4:junit4] > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
[junit4:junit4] > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] > Caused by: java.lang.AssertionError: Directory not closed: MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227539tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@1df1d32b))
[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=2680, name=RecoveryThread, state=RUNNABLE, group=TGRP-RecoveryZkTest], registration stack trace below.
[junit4:junit4] > at java.lang.Thread.getStackTrace(Thread.java:1479)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeAtEnd(RandomizedContext.java:150)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.closeAfterSuite(LuceneTestCase.java:525)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.wrapDirectory(LuceneTestCase.java:991)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:883)
[junit4:junit4] > at org.apache.lucene.util.LuceneTestCase.newDirectory(LuceneTestCase.java:875)
[junit4:junit4] > at org.apache.solr.core.MockDirectoryFactory.create(MockDirectoryFactory.java:37)
[junit4:junit4] > at org.apache.solr.core.CachingDirectoryFactory.get(CachingDirectoryFactory.java:329)
[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(RateLimitedDirectoryWrapper(org.apache.lucene.store.SimpleFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/index2753227540tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f306042))
[junit4:junit4] > at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4] > at org.apache.lucene.util.CloseableDirectory.close(CloseableDirectory.java:47)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:602)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2$1.apply(RandomizedRunner.java:599)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedContext.closeResources(RandomizedContext.java:167)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$2.afterAlways(RandomizedRunner.java:615)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] Completed on J1 in 36.10s, 1 test, 2 errors <<< FAILURES!
[...truncated 407 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:361: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1212: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:876: There were test failures: 273 suites, 1149 tests, 2 suite-level errors, 13 ignored (7 assumptions)
Total time: 38 minutes 30 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.6.0_41 -XX:+UseSerialGC
Email was triggered for: Failure
Sending email for trigger: Failure