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/14 11:12:52 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.7.0_15) - Build # 4673
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4673/
Java: 64bit/jdk1.7.0_15 -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([ECEA30D4E9CBBC88:6D0CBECC9E94DCB4]:0)
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertTrue(Assert.java:54)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:196)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9375 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T2677 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 5 T2677 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-SyncSliceTest-1363255699881
[junit4:junit4] 2> 6 T2677 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 6 T2678 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 7 T2678 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 8 T2678 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 8 T2678 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 8 T2678 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 10 T2678 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.SyncSliceTest-1363255699880/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 106 T2677 oasc.ZkTestServer.run start zk server on port:56781
[junit4:junit4] 2> 107 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5893f43b
[junit4:junit4] 2> 108 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108 T2683 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 109 T2683 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 109 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50679
[junit4:junit4] 2> 110 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50679
[junit4:junit4] 2> 111 T2681 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 148 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0000 with negotiated timeout 10000 for client /127.0.0.1:50679
[junit4:junit4] 2> 149 T2683 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0000, negotiated timeout = 10000
[junit4:junit4] 2> 149 T2684 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5893f43b name:ZooKeeperConnection Watcher:127.0.0.1:56781 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 149 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 150 T2677 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 152 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad0000
[junit4:junit4] 2> 153 T2684 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 153 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad0000 closed
[junit4:junit4] 2> 153 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50679 which had sessionid 0x13d685f29ad0000
[junit4:junit4] 2> 154 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@583944d7
[junit4:junit4] 2> 155 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 155 T2685 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 155 T2685 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 155 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50680
[junit4:junit4] 2> 155 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50680
[junit4:junit4] 2> 156 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0001 with negotiated timeout 10000 for client /127.0.0.1:50680
[junit4:junit4] 2> 156 T2685 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0001, negotiated timeout = 10000
[junit4:junit4] 2> 156 T2686 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@583944d7 name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 156 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 157 T2677 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 160 T2677 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 161 T2677 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 164 T2677 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 166 T2677 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> 167 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 172 T2677 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> 173 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 176 T2677 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> 176 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 178 T2677 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> 178 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 180 T2677 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> 180 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 182 T2677 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> 183 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 184 T2677 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> 185 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 186 T2677 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> 187 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 188 T2677 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> 189 T2677 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 190 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad0001
[junit4:junit4] 2> 191 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50680 which had sessionid 0x13d685f29ad0001
[junit4:junit4] 2> 191 T2686 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 191 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad0001 closed
[junit4:junit4] 2> 251 T2677 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 254 T2677 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51003
[junit4:junit4] 2> 254 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 255 T2677 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 255 T2677 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.SyncSliceTest-controljetty-1363255700067
[junit4:junit4] 2> 255 T2677 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.SyncSliceTest-controljetty-1363255700067/solr.xml
[junit4:junit4] 2> 255 T2677 oasc.CoreContainer.<init> New CoreContainer 681522664
[junit4:junit4] 2> 256 T2677 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.SyncSliceTest-controljetty-1363255700067/'
[junit4:junit4] 2> 256 T2677 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.SyncSliceTest-controljetty-1363255700067/'
[junit4:junit4] 2> 272 T2677 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 273 T2677 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 273 T2677 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 273 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 274 T2677 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 274 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 274 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 275 T2677 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 275 T2677 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 275 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 281 T2677 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 290 T2677 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56781/solr
[junit4:junit4] 2> 290 T2677 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 290 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@48ecd39e
[junit4:junit4] 2> 291 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 293 T2696 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 294 T2696 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 294 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50681
[junit4:junit4] 2> 294 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50681
[junit4:junit4] 2> 295 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0002 with negotiated timeout 20000 for client /127.0.0.1:50681
[junit4:junit4] 2> 295 T2696 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0002, negotiated timeout = 20000
[junit4:junit4] 2> 295 T2697 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48ecd39e name:ZooKeeperConnection Watcher:127.0.0.1:56781 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 295 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 296 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad0002
[junit4:junit4] 2> 297 T2697 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 297 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50681 which had sessionid 0x13d685f29ad0002
[junit4:junit4] 2> 297 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad0002 closed
[junit4:junit4] 2> 297 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 299 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@114c8460
[junit4:junit4] 2> 300 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 300 T2698 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 301 T2698 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 301 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50682
[junit4:junit4] 2> 301 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50682
[junit4:junit4] 2> 302 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0003 with negotiated timeout 20000 for client /127.0.0.1:50682
[junit4:junit4] 2> 302 T2698 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0003, negotiated timeout = 20000
[junit4:junit4] 2> 302 T2699 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@114c8460 name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 302 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 304 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 305 T2677 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 306 T2677 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51003_
[junit4:junit4] 2> 307 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:51003_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:51003_
[junit4:junit4] 2> 307 T2677 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51003_
[junit4:junit4] 2> 309 T2677 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 312 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 313 T2677 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 316 T2677 oasc.Overseer.start Overseer (id=89342325547663363-127.0.0.1:51003_-n_0000000000) starting
[junit4:junit4] 2> 316 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 317 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 319 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 320 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 320 T2701 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 320 T2677 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 322 T2677 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 323 T2677 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 325 T2700 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 327 T2702 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.SyncSliceTest-controljetty-1363255700067/collection1
[junit4:junit4] 2> 327 T2702 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 327 T2702 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 327 T2702 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 328 T2702 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.SyncSliceTest-controljetty-1363255700067/collection1/'
[junit4:junit4] 2> 328 T2702 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1363255700067/collection1/lib/README' to classloader
[junit4:junit4] 2> 329 T2702 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1363255700067/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 349 T2702 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 374 T2702 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 375 T2702 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 380 T2702 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 654 T2702 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 658 T2702 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 660 T2702 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 669 T2702 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 672 T2702 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 675 T2702 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 676 T2702 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 676 T2702 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 676 T2702 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 677 T2702 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 677 T2702 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 677 T2702 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 677 T2702 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.SyncSliceTest-controljetty-1363255700067/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/control/data/
[junit4:junit4] 2> 677 T2702 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@163b8a2f
[junit4:junit4] 2> 678 T2702 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 678 T2702 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/control/data forceNew: false
[junit4:junit4] 2> 679 T2702 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363255699880/control/data/index/
[junit4:junit4] 2> 679 T2702 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363255699880/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 679 T2702 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/control/data/index forceNew: false
[junit4:junit4] 2> 681 T2702 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@2f70590e lockFactory=org.apache.lucene.store.NativeFSLockFactory@45434606; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 681 T2702 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 683 T2702 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 683 T2702 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 684 T2702 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 684 T2702 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 685 T2702 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 685 T2702 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 685 T2702 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 686 T2702 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 686 T2702 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 689 T2702 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 692 T2702 oass.SolrIndexSearcher.<init> Opening Searcher@4172ca2f main
[junit4:junit4] 2> 692 T2702 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/control/data/tlog
[junit4:junit4] 2> 693 T2702 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 693 T2702 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 696 T2703 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4172ca2f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 696 T2702 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 696 T2702 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 697 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 1827 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1828 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:51003_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51003"}
[junit4:junit4] 2> 1828 T2700 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1828 T2700 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 1828 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 1832 T2699 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> 2699 T2702 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2699 T2702 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51003 collection:control_collection shard:shard1
[junit4:junit4] 2> 2700 T2702 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2704 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:delete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2704 T2702 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2705 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2706 T2702 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2706 T2702 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2706 T2702 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51003/collection1/
[junit4:junit4] 2> 2706 T2702 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2706 T2702 oasc.SyncStrategy.syncToMe http://127.0.0.1:51003/collection1/ has no replicas
[junit4:junit4] 2> 2707 T2702 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51003/collection1/
[junit4:junit4] 2> 2707 T2702 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2709 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3334 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3373 T2699 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> 3411 T2702 oasc.ZkController.register We are http://127.0.0.1:51003/collection1/ and leader is http://127.0.0.1:51003/collection1/
[junit4:junit4] 2> 3411 T2702 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51003
[junit4:junit4] 2> 3412 T2702 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3412 T2702 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3412 T2702 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3413 T2702 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3414 T2677 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3414 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3415 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3417 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3418 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@463f218
[junit4:junit4] 2> 3418 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3418 T2705 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3419 T2705 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 3419 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50683
[junit4:junit4] 2> 3419 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50683
[junit4:junit4] 2> 3420 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0004 with negotiated timeout 10000 for client /127.0.0.1:50683
[junit4:junit4] 2> 3420 T2705 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0004, negotiated timeout = 10000
[junit4:junit4] 2> 3420 T2706 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@463f218 name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3420 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3422 T2677 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3423 T2677 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3482 T2677 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3484 T2677 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36753
[junit4:junit4] 2> 3485 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3485 T2677 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3486 T2677 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.SyncSliceTest-jetty1-1363255703298
[junit4:junit4] 2> 3486 T2677 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.SyncSliceTest-jetty1-1363255703298/solr.xml
[junit4:junit4] 2> 3486 T2677 oasc.CoreContainer.<init> New CoreContainer 145494074
[junit4:junit4] 2> 3487 T2677 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.SyncSliceTest-jetty1-1363255703298/'
[junit4:junit4] 2> 3487 T2677 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.SyncSliceTest-jetty1-1363255703298/'
[junit4:junit4] 2> 3505 T2677 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3506 T2677 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3506 T2677 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3506 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3507 T2677 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3507 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3507 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3508 T2677 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3508 T2677 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3508 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3513 T2677 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3521 T2677 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56781/solr
[junit4:junit4] 2> 3521 T2677 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3522 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1bad6fe6
[junit4:junit4] 2> 3522 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3523 T2716 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3523 T2716 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 3523 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50684
[junit4:junit4] 2> 3524 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50684
[junit4:junit4] 2> 3525 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0005 with negotiated timeout 20000 for client /127.0.0.1:50684
[junit4:junit4] 2> 3525 T2716 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0005, negotiated timeout = 20000
[junit4:junit4] 2> 3525 T2717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bad6fe6 name:ZooKeeperConnection Watcher:127.0.0.1:56781 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3526 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3527 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad0005
[junit4:junit4] 2> 3527 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50684 which had sessionid 0x13d685f29ad0005
[junit4:junit4] 2> 3527 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad0005 closed
[junit4:junit4] 2> 3527 T2717 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3528 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3530 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5a948260
[junit4:junit4] 2> 3530 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3531 T2718 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3531 T2718 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 3531 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50685
[junit4:junit4] 2> 3531 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50685
[junit4:junit4] 2> 3532 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0006 with negotiated timeout 20000 for client /127.0.0.1:50685
[junit4:junit4] 2> 3532 T2718 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0006, negotiated timeout = 20000
[junit4:junit4] 2> 3532 T2719 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a948260 name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3532 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3533 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3534 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3534 T2677 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4536 T2677 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36753_
[junit4:junit4] 2> 4537 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:36753_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:36753_
[junit4:junit4] 2> 4537 T2677 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36753_
[junit4:junit4] 2> 4539 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 4540 T2706 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4540 T2719 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4541 T2699 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4543 T2720 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.SyncSliceTest-jetty1-1363255703298/collection1
[junit4:junit4] 2> 4544 T2720 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4544 T2720 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4544 T2720 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4545 T2720 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.SyncSliceTest-jetty1-1363255703298/collection1/'
[junit4:junit4] 2> 4545 T2720 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1363255703298/collection1/lib/README' to classloader
[junit4:junit4] 2> 4546 T2720 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1363255703298/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4565 T2720 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 4589 T2720 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4590 T2720 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4593 T2720 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 4857 T2720 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 4862 T2720 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 4864 T2720 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 4872 T2720 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4875 T2720 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4877 T2720 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4878 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 4878 T2720 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 4878 T2720 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 4878 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:51003_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51003"}
[junit4:junit4] 2> 4878 T2720 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4879 T2720 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 4880 T2720 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 4880 T2720 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 4880 T2720 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.SyncSliceTest-jetty1-1363255703298/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty1/
[junit4:junit4] 2> 4880 T2720 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@163b8a2f
[junit4:junit4] 2> 4881 T2720 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 4881 T2720 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty1 forceNew: false
[junit4:junit4] 2> 4881 T2720 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty1/index/
[junit4:junit4] 2> 4881 T2720 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 4882 T2699 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> 4882 T2706 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> 4882 T2720 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty1/index forceNew: false
[junit4:junit4] 2> 4882 T2719 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> 4883 T2720 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 4884 T2720 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 4885 T2720 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 4885 T2720 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 4885 T2720 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 4886 T2720 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 4886 T2720 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 4886 T2720 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 4886 T2720 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 4887 T2720 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 4887 T2720 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 4889 T2720 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 4891 T2720 oass.SolrIndexSearcher.<init> Opening Searcher@31594ef7 main
[junit4:junit4] 2> 4891 T2720 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty1/tlog
[junit4:junit4] 2> 4891 T2720 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 4892 T2720 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 4894 T2721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@31594ef7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 4896 T2720 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 4896 T2720 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6384 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6385 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:36753_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36753"}
[junit4:junit4] 2> 6385 T2700 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6385 T2700 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6398 T2706 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> 6398 T2719 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> 6398 T2699 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> 6897 T2720 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6898 T2720 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36753 collection:collection1 shard:shard1
[junit4:junit4] 2> 6898 T2720 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 6903 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0006 type:delete cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 6903 T2720 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 6904 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6905 T2720 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 6905 T2720 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 6905 T2720 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36753/collection1/
[junit4:junit4] 2> 6905 T2720 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 6905 T2720 oasc.SyncStrategy.syncToMe http://127.0.0.1:36753/collection1/ has no replicas
[junit4:junit4] 2> 6905 T2720 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36753/collection1/
[junit4:junit4] 2> 6906 T2720 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 6908 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7901 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7907 T2699 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> 7907 T2706 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> 7907 T2719 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> 7911 T2720 oasc.ZkController.register We are http://127.0.0.1:36753/collection1/ and leader is http://127.0.0.1:36753/collection1/
[junit4:junit4] 2> 7911 T2720 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36753
[junit4:junit4] 2> 7911 T2720 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 7911 T2720 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 7912 T2720 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 7959 T2720 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7960 T2677 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 7961 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 7961 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8014 T2677 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8017 T2677 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39783
[junit4:junit4] 2> 8017 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8018 T2677 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8018 T2677 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.SyncSliceTest-jetty2-1363255707838
[junit4:junit4] 2> 8018 T2677 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.SyncSliceTest-jetty2-1363255707838/solr.xml
[junit4:junit4] 2> 8018 T2677 oasc.CoreContainer.<init> New CoreContainer 955111156
[junit4:junit4] 2> 8019 T2677 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.SyncSliceTest-jetty2-1363255707838/'
[junit4:junit4] 2> 8019 T2677 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.SyncSliceTest-jetty2-1363255707838/'
[junit4:junit4] 2> 8034 T2677 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8035 T2677 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8035 T2677 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8035 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8036 T2677 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8036 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8036 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8037 T2677 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8037 T2677 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8037 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8042 T2677 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8049 T2677 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56781/solr
[junit4:junit4] 2> 8050 T2677 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8050 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@833b708
[junit4:junit4] 2> 8051 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8051 T2732 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8052 T2732 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 8052 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50709
[junit4:junit4] 2> 8052 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50709
[junit4:junit4] 2> 8054 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0007 with negotiated timeout 20000 for client /127.0.0.1:50709
[junit4:junit4] 2> 8054 T2732 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0007, negotiated timeout = 20000
[junit4:junit4] 2> 8054 T2733 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@833b708 name:ZooKeeperConnection Watcher:127.0.0.1:56781 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8054 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8055 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad0007
[junit4:junit4] 2> 8055 T2733 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8056 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50709 which had sessionid 0x13d685f29ad0007
[junit4:junit4] 2> 8055 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad0007 closed
[junit4:junit4] 2> 8056 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8058 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@77e3dbaa
[junit4:junit4] 2> 8059 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8059 T2734 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8059 T2734 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 8059 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50710
[junit4:junit4] 2> 8060 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50710
[junit4:junit4] 2> 8060 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0008 with negotiated timeout 20000 for client /127.0.0.1:50710
[junit4:junit4] 2> 8060 T2734 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0008, negotiated timeout = 20000
[junit4:junit4] 2> 8061 T2735 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@77e3dbaa name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8061 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8062 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8062 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8063 T2677 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9065 T2677 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39783_
[junit4:junit4] 2> 9066 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad0008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:39783_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:39783_
[junit4:junit4] 2> 9066 T2677 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39783_
[junit4:junit4] 2> 9068 T2699 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> 9069 T2706 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9069 T2719 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9069 T2735 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9069 T2706 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> 9069 T2719 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> 9070 T2699 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9073 T2736 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.SyncSliceTest-jetty2-1363255707838/collection1
[junit4:junit4] 2> 9073 T2736 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9074 T2736 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9074 T2736 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9075 T2736 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.SyncSliceTest-jetty2-1363255707838/collection1/'
[junit4:junit4] 2> 9075 T2736 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1363255707838/collection1/lib/README' to classloader
[junit4:junit4] 2> 9075 T2736 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1363255707838/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9104 T2736 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 9128 T2736 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9129 T2736 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9132 T2736 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9392 T2736 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9397 T2736 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9399 T2736 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9406 T2736 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9409 T2736 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9411 T2736 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9412 T2736 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9412 T2736 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9412 T2736 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9413 T2736 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9413 T2736 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9413 T2736 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9413 T2736 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.SyncSliceTest-jetty2-1363255707838/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2/
[junit4:junit4] 2> 9414 T2736 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@163b8a2f
[junit4:junit4] 2> 9414 T2736 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9414 T2736 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2 forceNew: false
[junit4:junit4] 2> 9415 T2736 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2/index/
[junit4:junit4] 2> 9415 T2736 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9415 T2736 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2/index forceNew: false
[junit4:junit4] 2> 9416 T2736 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9416 T2736 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9418 T2736 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9418 T2736 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9419 T2736 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9419 T2736 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9419 T2736 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9419 T2736 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9420 T2736 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9420 T2736 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9420 T2736 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9423 T2736 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9425 T2736 oass.SolrIndexSearcher.<init> Opening Searcher@4cc41bf5 main
[junit4:junit4] 2> 9425 T2736 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2/tlog
[junit4:junit4] 2> 9426 T2736 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9426 T2736 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9429 T2737 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4cc41bf5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9430 T2736 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9430 T2736 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 9460 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9461 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:36753_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36753"}
[junit4:junit4] 2> 9463 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39783_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39783"}
[junit4:junit4] 2> 9463 T2700 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 9463 T2700 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 9465 T2735 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> 9465 T2719 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> 9465 T2706 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> 9465 T2699 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> 10431 T2736 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 10431 T2736 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39783 collection:collection1 shard:shard1
[junit4:junit4] 2> 10433 T2736 oasc.ZkController.register We are http://127.0.0.1:39783/collection1/ and leader is http://127.0.0.1:36753/collection1/
[junit4:junit4] 2> 10433 T2736 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39783
[junit4:junit4] 2> 10433 T2736 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 10434 T2736 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C442 name=collection1 org.apache.solr.core.SolrCore@78039b0a url=http://127.0.0.1:39783/collection1 node=127.0.0.1:39783_ C442_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:39783_, base_url=http://127.0.0.1:39783}
[junit4:junit4] 2> 10434 T2738 C442 P39783 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 10434 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 10434 T2736 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 10434 T2738 C442 P39783 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 10434 T2738 C442 P39783 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 10435 T2677 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 10435 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 10436 T2738 C442 P39783 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 10436 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 10489 T2677 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 10491 T2677 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51593
[junit4:junit4] 2> 10492 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 10492 T2677 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 10493 T2677 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.SyncSliceTest-jetty3-1363255710313
[junit4:junit4] 2> 10493 T2677 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.SyncSliceTest-jetty3-1363255710313/solr.xml
[junit4:junit4] 2> 10493 T2677 oasc.CoreContainer.<init> New CoreContainer 1466497320
[junit4:junit4] 2> 10494 T2677 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.SyncSliceTest-jetty3-1363255710313/'
[junit4:junit4] 2> 10494 T2677 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.SyncSliceTest-jetty3-1363255710313/'
[junit4:junit4] 2> 10509 T2677 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 10510 T2677 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 10510 T2677 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 10510 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 10510 T2677 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 10511 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 10511 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 10511 T2677 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 10511 T2677 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 10512 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 10516 T2677 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 10524 T2677 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56781/solr
[junit4:junit4] 2> 10524 T2677 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 10525 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@7969f009
[junit4:junit4] 2> 10525 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 10526 T2749 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 10526 T2749 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 10527 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50718
[junit4:junit4] 2> 10527 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50718
[junit4:junit4] 2> 10527 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad0009 with negotiated timeout 20000 for client /127.0.0.1:50718
[junit4:junit4] 2> 10528 T2749 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad0009, negotiated timeout = 20000
[junit4:junit4] 2> 10528 T2750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7969f009 name:ZooKeeperConnection Watcher:127.0.0.1:56781 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 10528 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 10529 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad0009
[junit4:junit4] 2> 10530 T2750 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 10530 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50718 which had sessionid 0x13d685f29ad0009
[junit4:junit4] 2> 10530 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad0009 closed
[junit4:junit4] 2> 10530 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 10532 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@73e6fb3d
[junit4:junit4] 2> 10533 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 10533 T2751 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 10534 T2751 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 10534 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50719
[junit4:junit4] 2> 10534 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50719
[junit4:junit4] 2> 10535 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad000a with negotiated timeout 20000 for client /127.0.0.1:50719
[junit4:junit4] 2> 10535 T2751 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad000a, negotiated timeout = 20000
[junit4:junit4] 2> 10535 T2752 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@73e6fb3d name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 10535 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 10536 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad000a type:create cxid:0x1 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 10537 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad000a type:create cxid:0x2 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 10538 T2677 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 10969 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 10970 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39783_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39783"}
[junit4:junit4] 2> 10972 T2706 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> 10972 T2735 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> 10972 T2719 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> 10972 T2699 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> 10972 T2752 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> 11439 T2715 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=3&state=recovering&nodeName=127.0.0.1:39783_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 11540 T2677 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51593_
[junit4:junit4] 2> 11540 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad000a type:delete cxid:0xd zxid:0x86 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:51593_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:51593_
[junit4:junit4] 2> 11541 T2677 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51593_
[junit4:junit4] 2> 11543 T2735 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> 11543 T2699 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> 11543 T2752 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> 11543 T2706 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11543 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 11543 T2719 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11544 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 11544 T2735 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11544 T2752 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11544 T2699 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 11547 T2753 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.SyncSliceTest-jetty3-1363255710313/collection1
[junit4:junit4] 2> 11547 T2753 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 11548 T2753 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 11548 T2753 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 11549 T2753 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.SyncSliceTest-jetty3-1363255710313/collection1/'
[junit4:junit4] 2> 11549 T2753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1363255710313/collection1/lib/README' to classloader
[junit4:junit4] 2> 11549 T2753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1363255710313/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 11580 T2753 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 11612 T2753 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 11613 T2753 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 11616 T2753 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 11893 T2753 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 11897 T2753 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 11899 T2753 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 11916 T2753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 11919 T2753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 11921 T2753 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 11922 T2753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 11923 T2753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 11923 T2753 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 11924 T2753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 11924 T2753 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 11924 T2753 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 11924 T2753 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.SyncSliceTest-jetty3-1363255710313/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3/
[junit4:junit4] 2> 11924 T2753 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@163b8a2f
[junit4:junit4] 2> 11925 T2753 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 11925 T2753 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3 forceNew: false
[junit4:junit4] 2> 11925 T2753 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3/index/
[junit4:junit4] 2> 11925 T2753 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 11925 T2753 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3/index forceNew: false
[junit4:junit4] 2> 11927 T2753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11927 T2753 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11928 T2753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 11928 T2753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 11929 T2753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 11929 T2753 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 11930 T2753 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 11930 T2753 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 11930 T2753 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 11930 T2753 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 11931 T2753 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 11933 T2753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 11935 T2753 oass.SolrIndexSearcher.<init> Opening Searcher@eb12a72 main
[junit4:junit4] 2> 11935 T2753 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3/tlog
[junit4:junit4] 2> 11935 T2753 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 11936 T2753 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 11940 T2754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@eb12a72 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 11942 T2753 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 11942 T2753 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12476 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12477 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:51593_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51593"}
[junit4:junit4] 2> 12477 T2700 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 12477 T2700 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 12480 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12480 T2752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12480 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12480 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12480 T2735 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12943 T2753 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 12944 T2753 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51593 collection:collection1 shard:shard1
[junit4:junit4] 2> 12946 T2753 oasc.ZkController.register We are http://127.0.0.1:51593/collection1/ and leader is http://127.0.0.1:36753/collection1/
[junit4:junit4] 2> 12946 T2753 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51593
[junit4:junit4] 2> 12946 T2753 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 12946 T2753 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C443 name=collection1 org.apache.solr.core.SolrCore@7f42c8d4 url=http://127.0.0.1:51593/collection1 node=127.0.0.1:51593_ C443_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51593_, base_url=http://127.0.0.1:51593}
[junit4:junit4] 2> 12947 T2755 C443 P51593 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 12947 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 12947 T2753 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12947 T2755 C443 P51593 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 12947 T2755 C443 P51593 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12948 T2755 C443 P51593 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12948 T2677 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 12948 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 12948 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13002 T2677 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 13004 T2677 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:51008
[junit4:junit4] 2> 13005 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 13005 T2677 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 13005 T2677 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.SyncSliceTest-jetty4-1363255712825
[junit4:junit4] 2> 13005 T2677 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.SyncSliceTest-jetty4-1363255712825/solr.xml
[junit4:junit4] 2> 13006 T2677 oasc.CoreContainer.<init> New CoreContainer 1323437137
[junit4:junit4] 2> 13006 T2677 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.SyncSliceTest-jetty4-1363255712825/'
[junit4:junit4] 2> 13006 T2677 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.SyncSliceTest-jetty4-1363255712825/'
[junit4:junit4] 2> 13022 T2677 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 13022 T2677 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 13023 T2677 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 13023 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 13023 T2677 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 13023 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 13024 T2677 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 13024 T2677 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 13024 T2677 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 13024 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 13029 T2677 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 13037 T2677 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:56781/solr
[junit4:junit4] 2> 13037 T2677 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 13038 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@5f178017
[junit4:junit4] 2> 13038 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13039 T2766 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13039 T2766 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 13039 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50732
[junit4:junit4] 2> 13040 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50732
[junit4:junit4] 2> 13040 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad000b with negotiated timeout 20000 for client /127.0.0.1:50732
[junit4:junit4] 2> 13041 T2766 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad000b, negotiated timeout = 20000
[junit4:junit4] 2> 13041 T2767 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f178017 name:ZooKeeperConnection Watcher:127.0.0.1:56781 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13041 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13042 T2682 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d685f29ad000b
[junit4:junit4] 2> 13042 T2767 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 13042 T2679 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50732 which had sessionid 0x13d685f29ad000b
[junit4:junit4] 2> 13042 T2677 oaz.ZooKeeper.close Session: 0x13d685f29ad000b closed
[junit4:junit4] 2> 13043 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 13045 T2677 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:56781/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@15e80d93
[junit4:junit4] 2> 13046 T2768 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:56781. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13045 T2677 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13046 T2768 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:56781, initiating session
[junit4:junit4] 2> 13046 T2679 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50733
[junit4:junit4] 2> 13046 T2679 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50733
[junit4:junit4] 2> 13047 T2681 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d685f29ad000c with negotiated timeout 20000 for client /127.0.0.1:50733
[junit4:junit4] 2> 13047 T2768 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:56781, sessionid = 0x13d685f29ad000c, negotiated timeout = 20000
[junit4:junit4] 2> 13047 T2769 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15e80d93 name:ZooKeeperConnection Watcher:127.0.0.1:56781/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13048 T2677 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13048 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad000c type:create cxid:0x1 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13049 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad000c type:create cxid:0x2 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13050 T2677 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> C442_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:39783_, base_url=http://127.0.0.1:39783}
[junit4:junit4] 2> 13440 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36753/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 13441 T2738 C442 P39783 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39783 START replicas=[http://127.0.0.1:36753/collection1/] nUpdates=100
[junit4:junit4] 2> 13441 T2738 C442 P39783 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 13442 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 13442 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 13442 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 13442 T2738 C442 P39783 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 13442 T2738 C442 P39783 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36753/collection1/. core=collection1
[junit4:junit4] 2> 13442 T2738 C442 P39783 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C444 name=collection1 org.apache.solr.core.SolrCore@5083c762 url=http://127.0.0.1:36753/collection1 node=127.0.0.1:36753_ C444_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:36753_, base_url=http://127.0.0.1:36753, leader=true}
[junit4:junit4] 2> 13445 T2713 C444 P36753 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 13445 T2715 C444 P36753 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 13447 T2715 C444 P36753 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13447 T2715 C444 P36753 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13447 T2715 C444 P36753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 13448 T2715 C444 P36753 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 13448 T2715 C444 P36753 oass.SolrIndexSearcher.<init> Opening Searcher@b28c46 realtime
[junit4:junit4] 2> 13448 T2715 C444 P36753 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 13449 T2715 C444 P36753 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 13449 T2738 C442 P39783 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 13449 T2738 C442 P39783 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 13451 T2712 C444 P36753 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 13451 T2712 C444 P36753 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 13452 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 13452 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 13452 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 13454 T2715 C444 P36753 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 13454 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 13455 T2738 C442 P39783 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty2/index.20130314070833329 forceNew: false
[junit4:junit4] 2> 13455 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@619552c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@61840045)) fullCopy=false
[junit4:junit4] 2> 13457 T2713 C444 P36753 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 13458 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 13458 T2738 C442 P39783 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 13458 T2738 C442 P39783 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 13459 T2738 C442 P39783 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 13459 T2738 C442 P39783 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 13459 T2738 C442 P39783 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 13460 T2738 C442 P39783 oass.SolrIndexSearcher.<init> Opening Searcher@12e6df6a main
[junit4:junit4] 2> 13460 T2737 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12e6df6a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 13461 T2738 C442 P39783 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@619552c7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@61840045))
[junit4:junit4] 2> 13461 T2738 C442 P39783 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 13461 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 13461 T2738 C442 P39783 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 13461 T2738 C442 P39783 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 13462 T2738 C442 P39783 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 13986 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13987 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:51593_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51593"}
[junit4:junit4] 2> 13989 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:39783_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39783"}
[junit4:junit4] 2> 13991 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 13991 T2769 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 13992 T2752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 13992 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 13992 T2735 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 13992 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 14052 T2677 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51008_
[junit4:junit4] 2> 14053 T2682 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d685f29ad000c type:delete cxid:0xd zxid:0x9d txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:51008_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:51008_
[junit4:junit4] 2> 14054 T2677 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51008_
[junit4:junit4] 2> 14056 T2735 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 14056 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 14056 T2752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 14056 T2769 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14056 T2706 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14056 T2769 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 14056 T2719 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14056 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 14057 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 14058 T2735 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14058 T2752 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14058 T2699 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 14061 T2772 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.SyncSliceTest-jetty4-1363255712825/collection1
[junit4:junit4] 2> 14061 T2772 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 14062 T2772 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 14062 T2772 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 14063 T2772 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.SyncSliceTest-jetty4-1363255712825/collection1/'
[junit4:junit4] 2> 14063 T2772 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1363255712825/collection1/lib/README' to classloader
[junit4:junit4] 2> 14064 T2772 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1363255712825/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 14084 T2772 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 14107 T2772 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 14108 T2772 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 14111 T2772 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 14378 T2772 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 14382 T2772 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 14384 T2772 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 14392 T2772 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14395 T2772 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14398 T2772 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14399 T2772 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 14399 T2772 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 14399 T2772 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14400 T2772 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 14400 T2772 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 14400 T2772 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14401 T2772 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.SyncSliceTest-jetty4-1363255712825/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4/
[junit4:junit4] 2> 14401 T2772 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@163b8a2f
[junit4:junit4] 2> 14401 T2772 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14401 T2772 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4 forceNew: false
[junit4:junit4] 2> 14402 T2772 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4/index/
[junit4:junit4] 2> 14402 T2772 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 14402 T2772 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4/index forceNew: false
[junit4:junit4] 2> 14403 T2772 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 14403 T2772 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 14404 T2772 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 14405 T2772 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 14405 T2772 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 14405 T2772 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 14406 T2772 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 14406 T2772 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 14406 T2772 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 14406 T2772 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 14406 T2772 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 14408 T2772 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 14410 T2772 oass.SolrIndexSearcher.<init> Opening Searcher@458cf786 main
[junit4:junit4] 2> 14411 T2772 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4/tlog
[junit4:junit4] 2> 14411 T2772 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 14411 T2772 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 14413 T2773 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@458cf786 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 14414 T2772 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 14415 T2772 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14951 T2714 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=4&state=recovering&nodeName=127.0.0.1:51593_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2000
[junit4:junit4] 2> 15497 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15497 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:51008_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51008"}
[junit4:junit4] 2> 15498 T2700 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 15498 T2700 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 15500 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 15500 T2735 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 15500 T2752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 15500 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 15500 T2769 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 15500 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 16416 T2772 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 16416 T2772 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51008 collection:collection1 shard:shard1
[junit4:junit4] 2> 16419 T2772 oasc.ZkController.register We are http://127.0.0.1:51008/collection1/ and leader is http://127.0.0.1:36753/collection1/
[junit4:junit4] 2> 16419 T2772 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51008
[junit4:junit4] 2> 16419 T2772 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 16419 T2772 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C445 name=collection1 org.apache.solr.core.SolrCore@4e3a4a86 url=http://127.0.0.1:51008/collection1 node=127.0.0.1:51008_ C445_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:51008_, base_url=http://127.0.0.1:51008}
[junit4:junit4] 2> 16419 T2774 C445 P51008 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 16419 T2772 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16419 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 16420 T2774 C445 P51008 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 16420 T2774 C445 P51008 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16420 T2677 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 16421 T2774 C445 P51008 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16421 T2677 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 16421 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16424 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16425 T2677 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 16425 T2677 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 16425 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C443_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51593_, base_url=http://127.0.0.1:51593}
[junit4:junit4] 2> 16952 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36753/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51593 START replicas=[http://127.0.0.1:36753/collection1/] nUpdates=100
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 16953 T2755 C443 P51593 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36753/collection1/. core=collection1
[junit4:junit4] 2> 16954 T2755 C443 P51593 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16955 T2715 C444 P36753 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 16957 T2712 C444 P36753 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 16957 T2712 C444 P36753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 16958 T2712 C444 P36753 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 16958 T2712 C444 P36753 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 16958 T2712 C444 P36753 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 1
[junit4:junit4] 2> 16959 T2755 C443 P51593 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 16959 T2755 C443 P51593 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 16960 T2715 C444 P36753 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 16961 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 16961 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 16961 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 16963 T2712 C444 P36753 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0
[junit4:junit4] 2> 16963 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 16964 T2755 C443 P51593 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty3/index.20130314070836838 forceNew: false
[junit4:junit4] 2> 16964 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@43113f2c lockFactory=org.apache.lucene.store.NativeFSLockFactory@2326d809)) fullCopy=false
[junit4:junit4] 2> 16966 T2714 C444 P36753 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 16967 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 16967 T2755 C443 P51593 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 16968 T2755 C443 P51593 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 16968 T2755 C443 P51593 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 16968 T2755 C443 P51593 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 16969 T2755 C443 P51593 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 16969 T2755 C443 P51593 oass.SolrIndexSearcher.<init> Opening Searcher@1c0ca951 main
[junit4:junit4] 2> 16969 T2754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c0ca951 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 16970 T2755 C443 P51593 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@43113f2c lockFactory=org.apache.lucene.store.NativeFSLockFactory@2326d809))
[junit4:junit4] 2> 16970 T2755 C443 P51593 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 16970 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 16970 T2755 C443 P51593 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 16970 T2755 C443 P51593 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16971 T2755 C443 P51593 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 17004 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17004 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:51008_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51008"}
[junit4:junit4] 2> 17007 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:51593_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51593"}
[junit4:junit4] 2> 17009 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 17009 T2735 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 17009 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 17009 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 17009 T2752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 17009 T2769 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 17424 T2713 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=5&state=recovering&nodeName=127.0.0.1:51008_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 17427 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18428 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C445_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:51008_, base_url=http://127.0.0.1:51008}
[junit4:junit4] 2> 19425 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36753/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 19425 T2774 C445 P51008 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:51008 START replicas=[http://127.0.0.1:36753/collection1/] nUpdates=100
[junit4:junit4] 2> 19426 T2774 C445 P51008 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 19426 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 19426 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 19426 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 19426 T2774 C445 P51008 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 19426 T2774 C445 P51008 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36753/collection1/. core=collection1
[junit4:junit4] 2> 19426 T2774 C445 P51008 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19428 T2713 C444 P36753 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 19429 T2715 C444 P36753 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 19429 T2715 C444 P36753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 19429 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19430 T2715 C444 P36753 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 19430 T2715 C444 P36753 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19430 T2715 C444 P36753 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 1
[junit4:junit4] 2> 19431 T2774 C445 P51008 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19431 T2774 C445 P51008 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 19433 T2713 C444 P36753 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 19433 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 19433 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 19433 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 19435 T2714 C444 P36753 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=0
[junit4:junit4] 2> 19436 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 19437 T2774 C445 P51008 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363255699880/jetty4/index.20130314070839311 forceNew: false
[junit4:junit4] 2> 19437 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5e902bc6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@33985b73)) fullCopy=false
[junit4:junit4] 2> 19439 T2715 C444 P36753 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 19439 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 19440 T2774 C445 P51008 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 19440 T2774 C445 P51008 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 19441 T2774 C445 P51008 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 19441 T2774 C445 P51008 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 19441 T2774 C445 P51008 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 19441 T2774 C445 P51008 oass.SolrIndexSearcher.<init> Opening Searcher@1f477726 main
[junit4:junit4] 2> 19442 T2773 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f477726 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 19442 T2774 C445 P51008 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(RateLimitedDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5e902bc6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@33985b73))
[junit4:junit4] 2> 19443 T2774 C445 P51008 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 19443 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 19443 T2774 C445 P51008 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 19443 T2774 C445 P51008 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19444 T2774 C445 P51008 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 20014 T2700 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20015 T2700 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:51008_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51008"}
[junit4:junit4] 2> 20018 T2769 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 20018 T2735 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 20018 T2699 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 20018 T2752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 20018 T2719 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 20018 T2706 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 20431 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20432 T2677 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C446 name=collection1 org.apache.solr.core.SolrCore@25aa6904 url=http://127.0.0.1:51003/collection1 node=127.0.0.1:51003_ C446_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51003_, base_url=http://127.0.0.1:51003, leader=true}
[junit4:junit4] 2> 20439 T2692 C446 P51003 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20441 T2692 C446 P51003 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@2f70590e lockFactory=org.apache.lucene.store.NativeFSLockFactory@45434606; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 20441 T2692 C446 P51003 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 20442 T2692 C446 P51003 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@2f70590e lockFactory=org.apache.lucene.store.NativeFSLockFactory@45434606; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@2f70590e lockFactory=org.apache.lucene.store.NativeFSLockFactory@45434606; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 20442 T2692 C446 P51003 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 20442 T2692 C446 P51003 oass.SolrIndexSearcher.<init> Opening Searcher@7a528a0d main
[junit4:junit4] 2> 20443 T2692 C446 P51003 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20443 T2703 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a528a0d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 20443 T2692 C446 P51003 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 20446 T2712 C444 P36753 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20446 T2712 C444 P36753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 20447 T2712 C444 P36753 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 20447 T2712 C444 P36753 oass.SolrIndexSearcher.<init> Opening Searcher@1d21874d main
[junit4:junit4] 2> 20447 T2712 C444 P36753 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20448 T2721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d21874d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 20448 T2712 C444 P36753 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:39783/collection1/, StdNode: http://127.0.0.1:51593/collection1/, StdNode: http://127.0.0.1:51008/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C445_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51008_, base_url=http://127.0.0.1:51008}
[junit4:junit4] 2> 20453 T2763 C445 P51008 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20454 T2763 C445 P51008 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 20455 T2763 C445 P51008 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 20456 T2763 C445 P51008 oass.SolrIndexSearcher.<init> Opening Searcher@7786b00 main
[junit4:junit4] 2> C442_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:39783_, base_url=http://127.0.0.1:39783}
[junit4:junit4] 2> 20456 T2730 C442 P39783 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20456 T2763 C445 P51008 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> C443_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51593_, base_url=http://127.0.0.1:51593}
[junit4:junit4] 2> 20456 T2748 C443 P51593 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20457 T2773 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7786b00 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 20457 T2763 C445 P51008 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 20457 T2730 C442 P39783 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 20458 T2748 C443 P51593 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 20458 T2730 C442 P39783 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 20458 T2748 C443 P51593 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 20458 T2730 C442 P39783 oass.SolrIndexSearcher.<init> Opening Searcher@932af79 main
[junit4:junit4] 2> 20459 T2748 C443 P51593 oass.SolrIndexSearcher.<init> Opening Searcher@304e400e main
[junit4:junit4] 2> 20459 T2730 C442 P39783 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20459 T2754 oasc.JmxMonitoredMap.put WARNING Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:239)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1763)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:129)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1640)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 20459 T2737 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@932af79 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 20459 T2748 C443 P51593 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20460 T2754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@304e400e main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 20460 T2730 C442 P39783 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 20460 T2748 C443 P51593 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 20461 T2712 C444 P36753 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 15
[junit4:junit4] 2> 20461 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20463 T2713 C444 P36753 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 20465 T2731 C442 P39783 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 20466 T2746 C443 P51593 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 20467 T2764 C445 P51008 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22470 T2692 C446 P51003 oass.SolrIndexSearcher.<init> Opening Searcher@4ad01c43 realtime
[junit4:junit4] 2> 22471 T2692 C446 P51003 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1429477232313630720)} 0 1
[junit4:junit4] 2> 22476 T2730 C442 P39783 /update {update.distrib=FROMLEADER&_version_=-1429477232316776448&update.from=http://127.0.0.1:36753/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429477232316776448)} 0 1
[junit4:junit4] 2> 22476 T2746 C443 P51593 /update {update.distrib=FROMLEADER&_version_=-1429477232316776448&update.from=http://127.0.0.1:36753/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429477232316776448)} 0 1
[junit4:junit4] 2> 22477 T2763 C445 P51008 /update {update.distrib=FROMLEADER&_version_=-1429477232316776448&update.from=http://127.0.0.1:36753/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429477232316776448)} 0 1
[junit4:junit4] 2> 22477 T2712 C444 P36753 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1429477232316776448)} 0 4
[junit4:junit4] 2> 22481 T2693 C446 P51003 /update {wt=javabin&version=2} {add=[0 (1429477232324116480)]} 0 1
[junit4:junit4] 2> 22488 T2747 C443 P51593 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429477232328310784)]} 0 1
[junit4:junit4] 2> 22488 T2764 C445 P51008 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429477232328310784)]} 0 1
[junit4:junit4] 2> 22488 T2731 C442 P39783 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429477232328310784)]} 0 1
[junit4:junit4] 2> 22489 T2714 C444 P36753 /update {wt=javabin&version=2} {add=[0 (1429477232328310784)]} 0 5
[junit4:junit4] 2> 22493 T2694 C446 P51003 /update {wt=javabin&version=2} {add=[1 (1429477232335650816)]} 0 2
[junit4:junit4] 2> 22499 T2748 C443 P51593 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429477232339845120)]} 0 1
[junit4:junit4] 2> 22500 T2765 C445 P51008 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429477232339845120)]} 0 2
[junit4:junit4] 2> 22500 T2728 C442 P39783 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429477232339845120)]} 0 2
[junit4:junit4] 2> 22501 T2715 C444 P36753 /update {wt=javabin&version=2} {add=[1 (1429477232339845120)]} 0 6
[junit4:junit4] 2> 22505 T2695 C446 P51003 /update {wt=javabin&version=2} {add=[2 (1429477232349282304)]} 0 1
[junit4:junit4] 2> 22513 T2745 C443 P51593 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1429477232353476608)]} 0 2
[junit4:junit4] 2> 22513 T2762 C445 P51008 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1429477232353476608)]} 0 2
[junit4:junit4] 2> 22514 T2713 C444 P36753 /update {test.distrib.skip.servers=http://127.0.0.1:39783/collection1/&wt=javabin&version=2} {add=[2 (1429477232353476608)]} 0 6
[junit4:junit4] 2> 22517 T2692 C446 P51003 /update {wt=javabin&version=2} {add=[3 (1429477232362913792)]} 0 0
[junit4:junit4] 2> 22522 T2763 C445 P51008 /update {distrib.from=http://127.0.0.1:36753/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1429477232365010944)]} 0 1
[junit4:junit4] 2> 22523 T2712 C444 P36753 /update {test.distrib.skip.servers=http://127.0.0.1:39783/collection1/&test.distrib.skip.servers=http://127.0.0.1:51593/collection1/&wt=javabin&version=2} {add=[3 (1429477232365010944)]} 0 4
[junit4:junit4] 2> 22525 T2693 C446 P51003 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22528 T2693 C446 P51003 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@2f70590e lockFactory=org.apache.lucene.store.NativeFSLockFactory@45434606; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@2f70590e lockFactory=org.apache.lucene.store.NativeFSLockFactory@45434606; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, _0.fdt, segments_3]
[junit4:junit4] 2> 22528 T2693 C446 P51003 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, _0.fdt, segments_3]
[junit4:junit4] 2> 22529 T2693 C446 P51003 oass.SolrIndexSearcher.<init> Opening Searcher@159608ec main
[junit4:junit4] 2> 22530 T2693 C446 P51003 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22531 T2703 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@159608ec main{StandardDirectoryReader(segments_3:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 22531 T2693 C446 P51003 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 22534 T2714 C444 P36753 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22535 T2714 C444 P36753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=5
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@73199590 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28cfae83; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_6,generation=6,filenames=[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, segments_6, _0.fdt]
[junit4:junit4] 2> 22535 T2714 C444 P36753 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, segments_6, _0.fdt]
[junit4:junit4] 2> 22536 T2714 C444 P36753 oass.SolrIndexSearcher.<init> Opening Searcher@77abd4cb main
[junit4:junit4] 2> 22536 T2714 C444 P36753 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22537 T2721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77abd4cb main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 22538 T2714 C444 P36753 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:39783/collection1/, StdNode: http://127.0.0.1:51593/collection1/, StdNode: http://127.0.0.1:51008/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 22540 T2764 C445 P51008 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22540 T2746 C443 P51593 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22540 T2729 C442 P39783 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22543 T2764 C445 P51008 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6a32fc1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@2345e4b0; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_6,generation=6,filenames=[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, segments_6, _0.fdt]
[junit4:junit4] 2> 22543 T2729 C442 P39783 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@1a8368e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a6cd8f1; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, _0.fdt, segments_4]
[junit4:junit4] 2> 22543 T2764 C445 P51008 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, segments_6, _0.fdt]
[junit4:junit4] 2> 22543 T2729 C442 P39783 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, _0.prx, _0.fdt, segments_4]
[junit4:junit4] 2> 22543 T2746 C443 P51593 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@61da705c lockFactory=org.apache.lucene.store.NativeFSLockFactory@41082231; maxCacheMB=0.734375 maxMergeSizeMB=0.8896484375))),segFN=segments_5,generation=5,filenames=[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, segments_5, _0.prx, _0.fdt]
[junit4:junit4] 2> 22544 T2764 C445 P51008 oass.SolrIndexSearcher.<init> Opening Searcher@2e635ffb main
[junit4:junit4] 2> 22544 T2729 C442 P39783 oass.SolrIndexSearcher.<init> Opening Searcher@148b279a main
[junit4:junit4] 2> 22544 T2746 C443 P51593 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[_0.tis, _0.nrm, _0.fnm, _0.tii, _0.frq, _0.fdx, _0.si, segments_5, _0.prx, _0.fdt]
[junit4:junit4] 2> 22545 T2729 C442 P39783 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22545 T2773 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e635ffb main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 22545 T2764 C445 P51008 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22545 T2737 oasc.JmxMonitoredMap.put WARNING Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:513)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:239)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1763)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:129)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1640)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 22546 T2764 C445 P51008 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 22546 T2746 C443 P51593 oass.SolrIndexSearcher.<init> Opening Searcher@51fdd3ef main
[junit4:junit4] 2> 22547 T2737 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@148b279a main{StandardDirectoryReader(segments_4:3:nrt _0(4.3):C2)}
[junit4:junit4] 2> 22547 T2746 C443 P51593 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22547 T2729 C442 P39783 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 22547 T2754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51fdd3ef main{StandardDirectoryReader(segments_5:3:nrt _0(4.3):C3)}
[junit4:junit4] 2> 22548 T2746 C443 P51593 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 22549 T2714 C444 P36753 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 22550 T2677 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 22551 T2677 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22552 T2677 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 22554 T2715 C444 P36753 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 22556 T2730 C442 P39783 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 22558 T2747 C443 P51593 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=0
[junit4:junit4] 2> 22560 T2765 C445 P51008 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 22561 T2677 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 22566 T2745 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 22566 T2745 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 22568 T2713 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 22569 T2713 oasc.SyncStrat
[...truncated too long message...]
nt port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=ECEA30D4E9CBBC88 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=da -Dtests.timezone=Brazil/East -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 46.8s J1 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([ECEA30D4E9CBBC88:6D0CBECC9E94DCB4]:0)
[junit4:junit4] > at org.junit.Assert.fail(Assert.java:92)
[junit4:junit4] > at org.junit.Assert.assertTrue(Assert.java:43)
[junit4:junit4] > at org.junit.Assert.assertTrue(Assert.java:54)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:196)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4] > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4] > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4] > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4] > at java.lang.reflect.Method.invoke(Method.java:601)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] > at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4] > at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4] > at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] > at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] > at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] > at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] > at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] > at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 46785 T2677 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 46788 T2676 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 4 leaked thread(s).
[junit4:junit4] 2> 46890 T2752 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 46890 T2752 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 46890 T2752 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 47125 T2680 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4] 2> 47995 T2769 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 47995 T2769 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 47995 T2769 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 47995 T2769 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=da, timezone=Brazil/East
[junit4:junit4] 2> NOTE: Linux 3.2.0-38-generic amd64/Oracle Corporation 1.7.0_15 (64-bit)/cpus=8,threads=6,free=155231224,total=385417216
[junit4:junit4] 2> NOTE: All tests run in this JVM: [NoCacheHeaderTest, DisMaxRequestHandlerTest, TestArbitraryIndexDir, TestFieldTypeCollectionResource, JSONWriterTest, TestNumberUtils, TestCollationField, ConvertedLegacyTest, CoreContainerCoreInitFailuresTest, TestPostingsSolrHighlighter, SpellPossibilityIteratorTest, DocValuesMultiTest, CachingDirectoryFactoryTest, TestSuggestSpellingConverter, HardAutoCommitTest, TestRandomFaceting, OpenCloseCoreStressTest, CurrencyFieldOpenExchangeTest, TestJmxMonitoredMap, TestStressLucene, XsltUpdateRequestHandlerTest, TestDistributedSearch, SolrPluginUtilsTest, TestFastOutputStream, ShardRoutingCustomTest, BasicZkTest, TestAtomicUpdateErrorCases, TestReload, NotRequiredUniqueKeyTest, BasicDistributedZk2Test, TestZkChroot, LeaderElectionIntegrationTest, TestCodecSupport, FieldAnalysisRequestHandlerTest, OpenExchangeRatesOrgProviderTest, TestRecovery, DirectUpdateHandlerTest, TestLMJelinekMercerSimilarityFactory, TestSolrXMLSerializer, TestJmxIntegration, TestStressReorder, TestLuceneMatchVersion, SortByFunctionTest, AliasIntegrationTest, TestFiltering, TestWordDelimiterFilterFactory, TestIndexingPerformance, RequestHandlersTest, DefaultValueUpdateProcessorTest, BadIndexSchemaTest, SolrCmdDistributorTest, TestSolrJ, IndexBasedSpellCheckerTest, TestFieldCollectionResource, TestBinaryResponseWriter, TimeZoneUtilsTest, StandardRequestHandlerTest, TestDefaultSimilarityFactory, TestCSVResponseWriter, DOMUtilTest, RequiredFieldsTest, CollectionsAPIDistributedZkTest, SyncSliceTest]
[junit4:junit4] Completed on J1 in 48.07s, 1 test, 1 failure <<< FAILURES!
[...truncated 414 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:1213: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:877: There were test failures: 272 suites, 1145 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 37 minutes 15 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.7.0_15 -XX:+UseParallelGC
Email was triggered for: Failure
Sending email for trigger: Failure