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 08:04:15 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_15) - Build # 4671
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4671/
Java: 32bit/jdk1.7.0_15 -client -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([634BFEC70A0731B7:E2AD70DF7D58518B]: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 9275 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 1 T1302 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /valc/hl
[junit4:junit4] 2> 4 T1302 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1363243827336
[junit4:junit4] 2> 5 T1302 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 6 T1303 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 6 T1303 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 6 T1303 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 7 T1303 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 7 T1303 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 7 T1303 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1363243827336/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 106 T1302 oasc.ZkTestServer.run start zk server on port:42201
[junit4:junit4] 2> 106 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@96cbb3
[junit4:junit4] 2> 107 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 107 T1308 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 107 T1308 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 108 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60543
[junit4:junit4] 2> 108 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60543
[junit4:junit4] 2> 108 T1306 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 547 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0000 with negotiated timeout 10000 for client /127.0.0.1:60543
[junit4:junit4] 2> 547 T1308 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0000, negotiated timeout = 10000
[junit4:junit4] 2> 548 T1309 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@96cbb3 name:ZooKeeperConnection Watcher:127.0.0.1:42201 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 549 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 549 T1302 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 555 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b0000
[junit4:junit4] 2> 556 T1309 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 556 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b0000 closed
[junit4:junit4] 2> 557 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@68dada
[junit4:junit4] 2> 559 T1310 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 560 T1310 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 566 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60543 which had sessionid 0x13d67aa008b0000
[junit4:junit4] 2> 561 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 567 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60544
[junit4:junit4] 2> 568 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60544
[junit4:junit4] 2> 569 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0001 with negotiated timeout 10000 for client /127.0.0.1:60544
[junit4:junit4] 2> 569 T1310 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0001, negotiated timeout = 10000
[junit4:junit4] 2> 570 T1311 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68dada name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 570 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 571 T1302 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 585 T1302 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 594 T1302 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 598 T1302 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 601 T1302 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> 601 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 613 T1302 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> 615 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 619 T1302 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> 620 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 622 T1302 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> 622 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 624 T1302 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> 624 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 627 T1302 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> 627 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 629 T1302 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> 630 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 632 T1302 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> 632 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 634 T1302 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> 634 T1302 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 636 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b0001
[junit4:junit4] 2> 636 T1311 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 637 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60544 which had sessionid 0x13d67aa008b0001
[junit4:junit4] 2> 636 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b0001 closed
[junit4:junit4] 2> 702 T1302 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 704 T1302 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49352
[junit4:junit4] 2> 705 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 705 T1302 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 705 T1302 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968
[junit4:junit4] 2> 706 T1302 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/solr.xml
[junit4:junit4] 2> 706 T1302 oasc.CoreContainer.<init> New CoreContainer 24258886
[junit4:junit4] 2> 707 T1302 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/'
[junit4:junit4] 2> 707 T1302 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/'
[junit4:junit4] 2> 726 T1302 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 727 T1302 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 727 T1302 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 727 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 728 T1302 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 728 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 728 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 729 T1302 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 729 T1302 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 729 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 737 T1302 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 755 T1302 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:42201/solr
[junit4:junit4] 2> 755 T1302 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 756 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@e17219
[junit4:junit4] 2> 757 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 757 T1321 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 757 T1321 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 757 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60545
[junit4:junit4] 2> 758 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60545
[junit4:junit4] 2> 760 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0002 with negotiated timeout 20000 for client /127.0.0.1:60545
[junit4:junit4] 2> 760 T1321 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0002, negotiated timeout = 20000
[junit4:junit4] 2> 760 T1322 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e17219 name:ZooKeeperConnection Watcher:127.0.0.1:42201 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 760 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 761 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b0002
[junit4:junit4] 2> 762 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60545 which had sessionid 0x13d67aa008b0002
[junit4:junit4] 2> 762 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b0002 closed
[junit4:junit4] 2> 762 T1322 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 762 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 766 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@8133c4
[junit4:junit4] 2> 767 T1323 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 768 T1323 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 768 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60546
[junit4:junit4] 2> 769 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60546
[junit4:junit4] 2> 769 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0003 with negotiated timeout 20000 for client /127.0.0.1:60546
[junit4:junit4] 2> 769 T1323 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0003, negotiated timeout = 20000
[junit4:junit4] 2> 773 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 774 T1324 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8133c4 name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 774 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 775 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 781 T1302 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 782 T1302 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49352_valc%2Fhl
[junit4:junit4] 2> 783 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49352_valc%2Fhl Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49352_valc%2Fhl
[junit4:junit4] 2> 783 T1302 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49352_valc%2Fhl
[junit4:junit4] 2> 785 T1302 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1014 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 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> 1014 T1302 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1024 T1302 oasc.Overseer.start Overseer (id=89341547468488707-127.0.0.1:49352_valc%2Fhl-n_0000000000) starting
[junit4:junit4] 2> 1025 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 1026 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 1026 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 1027 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 1028 T1326 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1029 T1302 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1031 T1302 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1033 T1302 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1036 T1325 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1043 T1327 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/collection1
[junit4:junit4] 2> 1044 T1327 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1045 T1327 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1045 T1327 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1046 T1327 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/collection1/'
[junit4:junit4] 2> 1047 T1327 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/collection1/lib/README' to classloader
[junit4:junit4] 2> 1048 T1327 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1083 T1327 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 1121 T1327 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1122 T1327 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 1127 T1327 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1553 T1327 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1559 T1327 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1562 T1327 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1571 T1327 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1574 T1327 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1577 T1327 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1577 T1327 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1578 T1327 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1578 T1327 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1579 T1327 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1579 T1327 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1579 T1327 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1579 T1327 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363243827968/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/control/data/
[junit4:junit4] 2> 1579 T1327 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c7a1e5
[junit4:junit4] 2> 1580 T1327 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1580 T1327 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/control/data forceNew: false
[junit4:junit4] 2> 1580 T1327 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363243827336/control/data/index/
[junit4:junit4] 2> 1581 T1327 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363243827336/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1581 T1327 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/control/data/index forceNew: false
[junit4:junit4] 2> 1582 T1327 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@162c83f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c8bca6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1582 T1327 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1584 T1327 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1584 T1327 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1584 T1327 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1585 T1327 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1585 T1327 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1585 T1327 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1585 T1327 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1586 T1327 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1586 T1327 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1588 T1327 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1591 T1327 oass.SolrIndexSearcher.<init> Opening Searcher@1218050 main
[junit4:junit4] 2> 1592 T1327 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/control/data/tlog
[junit4:junit4] 2> 1592 T1327 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1593 T1327 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1596 T1328 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1218050 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1598 T1327 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1598 T1327 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1599 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 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> 2539 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2540 T1325 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:49352_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49352/valc/hl"}
[junit4:junit4] 2> 2540 T1325 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2540 T1325 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2541 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 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> 2544 T1324 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> 2601 T1327 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2602 T1327 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49352/valc/hl collection:control_collection shard:shard1
[junit4:junit4] 2> 2603 T1327 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2611 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 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> 2612 T1327 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2613 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2615 T1327 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2616 T1327 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2616 T1327 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49352/valc/hl/collection1/
[junit4:junit4] 2> 2616 T1327 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2617 T1327 oasc.SyncStrategy.syncToMe http://127.0.0.1:49352/valc/hl/collection1/ has no replicas
[junit4:junit4] 2> 2617 T1327 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49352/valc/hl/collection1/
[junit4:junit4] 2> 2618 T1327 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2624 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4048 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 4057 T1324 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> 4087 T1327 oasc.ZkController.register We are http://127.0.0.1:49352/valc/hl/collection1/ and leader is http://127.0.0.1:49352/valc/hl/collection1/
[junit4:junit4] 2> 4088 T1327 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49352/valc/hl
[junit4:junit4] 2> 4088 T1327 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 4088 T1327 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 4088 T1327 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 4089 T1327 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 4090 T1302 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 4091 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 4091 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 4094 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 4095 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@161aa52
[junit4:junit4] 2> 4095 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4095 T1330 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4096 T1330 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 4096 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60548
[junit4:junit4] 2> 4096 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60548
[junit4:junit4] 2> 4097 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0004 with negotiated timeout 10000 for client /127.0.0.1:60548
[junit4:junit4] 2> 4097 T1330 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0004, negotiated timeout = 10000
[junit4:junit4] 2> 4098 T1331 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@161aa52 name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4098 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4099 T1302 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4101 T1302 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4157 T1302 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4158 T1302 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42619
[junit4:junit4] 2> 4159 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4159 T1302 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4160 T1302 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433
[junit4:junit4] 2> 4160 T1302 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/solr.xml
[junit4:junit4] 2> 4160 T1302 oasc.CoreContainer.<init> New CoreContainer 30027304
[junit4:junit4] 2> 4161 T1302 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/'
[junit4:junit4] 2> 4161 T1302 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/'
[junit4:junit4] 2> 4182 T1302 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 4182 T1302 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4182 T1302 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4183 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4183 T1302 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4183 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4183 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4184 T1302 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4184 T1302 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4184 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4191 T1302 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4201 T1302 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:42201/solr
[junit4:junit4] 2> 4202 T1302 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4202 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1acea70
[junit4:junit4] 2> 4203 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4203 T1341 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4204 T1341 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 4204 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60549
[junit4:junit4] 2> 4204 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60549
[junit4:junit4] 2> 4205 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0005 with negotiated timeout 20000 for client /127.0.0.1:60549
[junit4:junit4] 2> 4205 T1341 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0005, negotiated timeout = 20000
[junit4:junit4] 2> 4205 T1342 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1acea70 name:ZooKeeperConnection Watcher:127.0.0.1:42201 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4206 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4207 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b0005
[junit4:junit4] 2> 4207 T1342 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4207 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60549 which had sessionid 0x13d67aa008b0005
[junit4:junit4] 2> 4207 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b0005 closed
[junit4:junit4] 2> 4208 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4210 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@726c52
[junit4:junit4] 2> 4211 T1343 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4211 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4211 T1343 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 4211 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60550
[junit4:junit4] 2> 4212 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60550
[junit4:junit4] 2> 4213 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0006 with negotiated timeout 20000 for client /127.0.0.1:60550
[junit4:junit4] 2> 4213 T1343 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0006, negotiated timeout = 20000
[junit4:junit4] 2> 4213 T1344 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@726c52 name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4214 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4215 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4216 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4218 T1302 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5221 T1302 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42619_valc%2Fhl
[junit4:junit4] 2> 5222 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:42619_valc%2Fhl Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:42619_valc%2Fhl
[junit4:junit4] 2> 5222 T1302 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42619_valc%2Fhl
[junit4:junit4] 2> 5225 T1331 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5225 T1344 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5225 T1324 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5225 T1324 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> 5231 T1345 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/collection1
[junit4:junit4] 2> 5231 T1345 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5232 T1345 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5232 T1345 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5233 T1345 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/collection1/'
[junit4:junit4] 2> 5233 T1345 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/collection1/lib/README' to classloader
[junit4:junit4] 2> 5234 T1345 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5263 T1345 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 5312 T1345 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5318 T1345 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5325 T1345 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5562 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5563 T1325 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:49352_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49352/valc/hl"}
[junit4:junit4] 2> 5624 T1331 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> 5624 T1344 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> 5624 T1324 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> 5709 T1345 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5715 T1345 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5718 T1345 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5728 T1345 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5731 T1345 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5734 T1345 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5735 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5735 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5735 T1345 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5736 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 5736 T1345 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 5736 T1345 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5737 T1345 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363243831433/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty1/
[junit4:junit4] 2> 5737 T1345 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c7a1e5
[junit4:junit4] 2> 5737 T1345 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 5738 T1345 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty1 forceNew: false
[junit4:junit4] 2> 5738 T1345 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty1/index/
[junit4:junit4] 2> 5738 T1345 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5738 T1345 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty1/index forceNew: false
[junit4:junit4] 2> 5739 T1345 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5740 T1345 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5741 T1345 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5742 T1345 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5742 T1345 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5743 T1345 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5743 T1345 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5743 T1345 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5744 T1345 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5744 T1345 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5745 T1345 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5748 T1345 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5751 T1345 oass.SolrIndexSearcher.<init> Opening Searcher@1a45081 main
[junit4:junit4] 2> 5751 T1345 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty1/tlog
[junit4:junit4] 2> 5751 T1345 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5752 T1345 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5765 T1346 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a45081 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5769 T1345 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5769 T1345 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 7147 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7148 T1325 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:42619_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42619/valc/hl"}
[junit4:junit4] 2> 7149 T1325 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 7149 T1325 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 8139 T1324 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> 8139 T1344 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> 8139 T1331 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> 8784 T1345 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 8785 T1345 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42619/valc/hl collection:collection1 shard:shard1
[junit4:junit4] 2> 8785 T1345 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 8790 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0006 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> 8791 T1345 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 8791 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8792 T1345 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 8792 T1345 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 8793 T1345 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 8793 T1345 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 8793 T1345 oasc.SyncStrategy.syncToMe http://127.0.0.1:42619/valc/hl/collection1/ has no replicas
[junit4:junit4] 2> 8793 T1345 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 8793 T1345 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 8798 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9642 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9763 T1324 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> 9763 T1344 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> 9763 T1331 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> 9801 T1345 oasc.ZkController.register We are http://127.0.0.1:42619/valc/hl/collection1/ and leader is http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 9802 T1345 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42619/valc/hl
[junit4:junit4] 2> 9802 T1345 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 9802 T1345 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 9802 T1345 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 9804 T1345 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9805 T1302 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 9805 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 9806 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 9883 T1302 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 9885 T1302 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53274
[junit4:junit4] 2> 9886 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 9887 T1302 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 9887 T1302 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141
[junit4:junit4] 2> 9887 T1302 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/solr.xml
[junit4:junit4] 2> 9888 T1302 oasc.CoreContainer.<init> New CoreContainer 156164
[junit4:junit4] 2> 9888 T1302 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/'
[junit4:junit4] 2> 9888 T1302 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/'
[junit4:junit4] 2> 9909 T1302 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 9910 T1302 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 9910 T1302 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 9910 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 9911 T1302 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 9911 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 9911 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 9912 T1302 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 9912 T1302 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 9912 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 9920 T1302 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 9932 T1302 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:42201/solr
[junit4:junit4] 2> 9933 T1302 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 9933 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@13ff194
[junit4:junit4] 2> 9934 T1357 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 9934 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 9942 T1357 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 9942 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60551
[junit4:junit4] 2> 9942 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60551
[junit4:junit4] 2> 9943 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0007 with negotiated timeout 20000 for client /127.0.0.1:60551
[junit4:junit4] 2> 9943 T1357 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0007, negotiated timeout = 20000
[junit4:junit4] 2> 9944 T1358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13ff194 name:ZooKeeperConnection Watcher:127.0.0.1:42201 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 9944 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 9945 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b0007
[junit4:junit4] 2> 9946 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60551 which had sessionid 0x13d67aa008b0007
[junit4:junit4] 2> 9946 T1358 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 9946 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b0007 closed
[junit4:junit4] 2> 9946 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 9949 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@179a306
[junit4:junit4] 2> 9950 T1359 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 9950 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 9951 T1359 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 9951 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60552
[junit4:junit4] 2> 9951 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60552
[junit4:junit4] 2> 9952 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0008 with negotiated timeout 20000 for client /127.0.0.1:60552
[junit4:junit4] 2> 9952 T1359 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0008, negotiated timeout = 20000
[junit4:junit4] 2> 9952 T1360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@179a306 name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 9952 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 9953 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9954 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9955 T1302 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 10962 T1302 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53274_valc%2Fhl
[junit4:junit4] 2> 10963 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b0008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:53274_valc%2Fhl Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:53274_valc%2Fhl
[junit4:junit4] 2> 10965 T1302 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53274_valc%2Fhl
[junit4:junit4] 2> 10967 T1344 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> 10967 T1331 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> 10968 T1324 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 10968 T1360 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 10968 T1324 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> 10970 T1344 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 10971 T1331 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 10976 T1361 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/collection1
[junit4:junit4] 2> 10977 T1361 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 10978 T1361 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 10978 T1361 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 10979 T1361 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/collection1/'
[junit4:junit4] 2> 10980 T1361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/collection1/lib/README' to classloader
[junit4:junit4] 2> 10980 T1361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 11011 T1361 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 11053 T1361 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 11054 T1361 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 11058 T1361 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 11268 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11268 T1325 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:42619_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42619/valc/hl"}
[junit4:junit4] 2> 11271 T1331 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> 11271 T1360 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> 11271 T1324 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> 11271 T1344 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> 11456 T1361 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 11465 T1361 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 11468 T1361 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 11477 T1361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 11480 T1361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 11483 T1361 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 11484 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 11485 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 11485 T1361 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 11486 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 11486 T1361 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 11486 T1361 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 11487 T1361 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363243837141/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2/
[junit4:junit4] 2> 11487 T1361 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c7a1e5
[junit4:junit4] 2> 11487 T1361 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 11488 T1361 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2 forceNew: false
[junit4:junit4] 2> 11488 T1361 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2/index/
[junit4:junit4] 2> 11488 T1361 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 11489 T1361 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2/index forceNew: false
[junit4:junit4] 2> 11490 T1361 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 11490 T1361 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 11491 T1361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 11492 T1361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 11492 T1361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 11493 T1361 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 11493 T1361 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 11493 T1361 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 11494 T1361 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 11494 T1361 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 11494 T1361 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 11497 T1361 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 11500 T1361 oass.SolrIndexSearcher.<init> Opening Searcher@2ee90d main
[junit4:junit4] 2> 11501 T1361 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2/tlog
[junit4:junit4] 2> 11501 T1361 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 11501 T1361 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 11506 T1362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2ee90d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 11507 T1361 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 11507 T1361 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12786 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12787 T1325 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:53274_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53274/valc/hl"}
[junit4:junit4] 2> 12787 T1325 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 12788 T1325 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 12883 T1324 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> 12883 T1344 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> 12884 T1331 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> 12883 T1360 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> 13509 T1361 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 13509 T1361 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53274/valc/hl collection:collection1 shard:shard1
[junit4:junit4] 2> 13512 T1361 oasc.ZkController.register We are http://127.0.0.1:53274/valc/hl/collection1/ and leader is http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 13512 T1361 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53274/valc/hl
[junit4:junit4] 2> 13512 T1361 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 13513 T1361 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C87 name=collection1 org.apache.solr.core.SolrCore@17e56e7 url=http://127.0.0.1:53274/valc/hl/collection1 node=127.0.0.1:53274_valc%2Fhl C87_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53274_valc%2Fhl, base_url=http://127.0.0.1:53274/valc/hl}
[junit4:junit4] 2> 13513 T1363 C87 P53274 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 13514 T1361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13517 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 13517 T1363 C87 P53274 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 13518 T1363 C87 P53274 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 13518 T1302 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 13519 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 13519 T1363 C87 P53274 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13519 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13597 T1302 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 13598 T1302 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59906
[junit4:junit4] 2> 13599 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 13599 T1302 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 13599 T1302 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854
[junit4:junit4] 2> 13600 T1302 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/solr.xml
[junit4:junit4] 2> 13600 T1302 oasc.CoreContainer.<init> New CoreContainer 7971396
[junit4:junit4] 2> 13600 T1302 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/'
[junit4:junit4] 2> 13601 T1302 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/'
[junit4:junit4] 2> 13622 T1302 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 13623 T1302 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 13623 T1302 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 13623 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 13624 T1302 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 13624 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 13624 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 13625 T1302 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 13625 T1302 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 13625 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 13632 T1302 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 13643 T1302 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:42201/solr
[junit4:junit4] 2> 13643 T1302 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 13644 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@50c0e9
[junit4:junit4] 2> 13645 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13645 T1374 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13651 T1374 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 13651 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60556
[junit4:junit4] 2> 13651 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60556
[junit4:junit4] 2> 13652 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b0009 with negotiated timeout 20000 for client /127.0.0.1:60556
[junit4:junit4] 2> 13652 T1374 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b0009, negotiated timeout = 20000
[junit4:junit4] 2> 13652 T1375 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50c0e9 name:ZooKeeperConnection Watcher:127.0.0.1:42201 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13652 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13653 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b0009
[junit4:junit4] 2> 13654 T1375 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 13654 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60556 which had sessionid 0x13d67aa008b0009
[junit4:junit4] 2> 13654 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b0009 closed
[junit4:junit4] 2> 13655 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 13658 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@f1a853
[junit4:junit4] 2> 13659 T1376 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13659 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13659 T1376 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 13659 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60557
[junit4:junit4] 2> 13660 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60557
[junit4:junit4] 2> 13660 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b000a with negotiated timeout 20000 for client /127.0.0.1:60557
[junit4:junit4] 2> 13660 T1376 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b000a, negotiated timeout = 20000
[junit4:junit4] 2> 13661 T1377 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f1a853 name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13661 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13662 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b000a type:create cxid:0x1 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13662 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b000a type:create cxid:0x2 zxid:0x82 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13664 T1302 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 14388 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14388 T1325 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:53274_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53274/valc/hl"}
[junit4:junit4] 2> 14391 T1344 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> 14391 T1324 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> 14391 T1331 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> 14391 T1377 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> 14391 T1360 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> 14523 T1337 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=3&state=recovering&nodeName=127.0.0.1:53274_valc%252Fhl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 14666 T1302 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59906_valc%2Fhl
[junit4:junit4] 2> 14666 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b000a type:delete cxid:0xd zxid:0x87 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59906_valc%2Fhl Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59906_valc%2Fhl
[junit4:junit4] 2> 14667 T1302 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59906_valc%2Fhl
[junit4:junit4] 2> 14669 T1344 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> 14669 T1360 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> 14669 T1331 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> 14669 T1324 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14670 T1324 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> 14670 T1344 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14671 T1331 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14671 T1360 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14671 T1377 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14672 T1377 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> 14676 T1378 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/collection1
[junit4:junit4] 2> 14676 T1378 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 14677 T1378 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 14677 T1378 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 14678 T1378 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/collection1/'
[junit4:junit4] 2> 14678 T1378 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/collection1/lib/README' to classloader
[junit4:junit4] 2> 14679 T1378 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 14720 T1378 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 14774 T1378 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 14775 T1378 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 14781 T1378 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 15210 T1378 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 15221 T1378 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 15224 T1378 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 15233 T1378 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 15237 T1378 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 15239 T1378 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 15240 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 15240 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 15240 T1378 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 15241 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 15241 T1378 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 15242 T1378 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 15242 T1378 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363243840854/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3/
[junit4:junit4] 2> 15242 T1378 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c7a1e5
[junit4:junit4] 2> 15243 T1378 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 15243 T1378 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3 forceNew: false
[junit4:junit4] 2> 15243 T1378 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3/index/
[junit4:junit4] 2> 15244 T1378 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 15244 T1378 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3/index forceNew: false
[junit4:junit4] 2> 15245 T1378 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15245 T1378 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15247 T1378 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 15248 T1378 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 15248 T1378 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 15249 T1378 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 15249 T1378 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 15250 T1378 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 15250 T1378 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 15251 T1378 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 15251 T1378 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 15254 T1378 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 15257 T1378 oass.SolrIndexSearcher.<init> Opening Searcher@1c7994b main
[junit4:junit4] 2> 15258 T1378 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3/tlog
[junit4:junit4] 2> 15258 T1378 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 15258 T1378 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 15262 T1379 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c7994b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 15264 T1378 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15264 T1378 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15896 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15897 T1325 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:59906_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59906/valc/hl"}
[junit4:junit4] 2> 15897 T1325 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 15897 T1325 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 15900 T1360 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> 15900 T1344 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> 15901 T1377 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> 15901 T1331 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> 15900 T1324 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> 16274 T1378 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 16274 T1378 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59906/valc/hl collection:collection1 shard:shard1
[junit4:junit4] 2> 16277 T1378 oasc.ZkController.register We are http://127.0.0.1:59906/valc/hl/collection1/ and leader is http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 16277 T1378 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59906/valc/hl
[junit4:junit4] 2> 16277 T1378 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 16277 T1378 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C88 name=collection1 org.apache.solr.core.SolrCore@8ba520 url=http://127.0.0.1:59906/valc/hl/collection1 node=127.0.0.1:59906_valc%2Fhl C88_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59906_valc%2Fhl, base_url=http://127.0.0.1:59906/valc/hl}
[junit4:junit4] 2> 16278 T1380 C88 P59906 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 16278 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 16278 T1378 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16279 T1380 C88 P59906 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 16279 T1380 C88 P59906 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16279 T1302 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 16280 T1380 C88 P59906 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16280 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 16281 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16363 T1302 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 16365 T1302 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49627
[junit4:junit4] 2> 16366 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 16366 T1302 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 16366 T1302 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616
[junit4:junit4] 2> 16367 T1302 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/solr.xml
[junit4:junit4] 2> 16367 T1302 oasc.CoreContainer.<init> New CoreContainer 27714160
[junit4:junit4] 2> 16368 T1302 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/'
[junit4:junit4] 2> 16368 T1302 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/'
[junit4:junit4] 2> 16389 T1302 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 16389 T1302 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 16390 T1302 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 16390 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 16390 T1302 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 16391 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 16391 T1302 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 16391 T1302 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 16392 T1302 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 16392 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 16402 T1302 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 16415 T1302 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:42201/solr
[junit4:junit4] 2> 16415 T1302 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 16416 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@128745f
[junit4:junit4] 2> 16417 T1391 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 16417 T1391 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 16418 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60560
[junit4:junit4] 2> 16418 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60560
[junit4:junit4] 2> 16418 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16419 T1391 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b000b, negotiated timeout = 20000
[junit4:junit4] 2> 16419 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b000b with negotiated timeout 20000 for client /127.0.0.1:60560
[junit4:junit4] 2> 16419 T1392 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@128745f name:ZooKeeperConnection Watcher:127.0.0.1:42201 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16419 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16420 T1307 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d67aa008b000b
[junit4:junit4] 2> 16421 T1392 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 16421 T1304 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60560 which had sessionid 0x13d67aa008b000b
[junit4:junit4] 2> 16421 T1302 oaz.ZooKeeper.close Session: 0x13d67aa008b000b closed
[junit4:junit4] 2> 16422 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 16425 T1302 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:42201/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1523841
[junit4:junit4] 2> 16427 T1393 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:42201. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 16426 T1302 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16427 T1304 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60561
[junit4:junit4] 2> 16427 T1393 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:42201, initiating session
[junit4:junit4] 2> 16427 T1304 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60561
[junit4:junit4] 2> 16428 T1306 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d67aa008b000c with negotiated timeout 20000 for client /127.0.0.1:60561
[junit4:junit4] 2> 16428 T1393 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:42201, sessionid = 0x13d67aa008b000c, negotiated timeout = 20000
[junit4:junit4] 2> 16428 T1394 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1523841 name:ZooKeeperConnection Watcher:127.0.0.1:42201/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16429 T1302 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16429 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b000c type:create cxid:0x1 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16430 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b000c type:create cxid:0x2 zxid:0x95 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16432 T1302 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> C87_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53274_valc%2Fhl, base_url=http://127.0.0.1:53274/valc/hl}
[junit4:junit4] 2> 16524 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42619/valc/hl/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 16525 T1363 C87 P53274 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53274/valc/hl START replicas=[http://127.0.0.1:42619/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 16527 T1363 C87 P53274 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 16527 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 16527 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 16527 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 16528 T1363 C87 P53274 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 16528 T1363 C87 P53274 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42619/valc/hl/collection1/. core=collection1
[junit4:junit4] 2> 16528 T1363 C87 P53274 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C89 name=collection1 org.apache.solr.core.SolrCore@af659d url=http://127.0.0.1:42619/valc/hl/collection1 node=127.0.0.1:42619_valc%2Fhl C89_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:42619_valc%2Fhl, base_url=http://127.0.0.1:42619/valc/hl, leader=true}
[junit4:junit4] 2> 16540 T1338 C89 P42619 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 16542 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 16543 T1340 C89 P42619 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 16549 T1340 C89 P42619 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 16550 T1340 C89 P42619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 16550 T1340 C89 P42619 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 16551 T1340 C89 P42619 oass.SolrIndexSearcher.<init> Opening Searcher@c0f0df realtime
[junit4:junit4] 2> 16551 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 16552 T1340 C89 P42619 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 16552 T1363 C87 P53274 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 16553 T1363 C87 P53274 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 16554 T1338 C89 P42619 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 16555 T1338 C89 P42619 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 16555 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 16556 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 16556 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 16557 T1339 C89 P42619 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 16558 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 16559 T1363 C87 P53274 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty2/index.20130314095043889 forceNew: false
[junit4:junit4] 2> 16559 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@9a1ffa lockFactory=org.apache.lucene.store.NativeFSLockFactory@1aa5d39) fullCopy=false
[junit4:junit4] 2> 16561 T1340 C89 P42619 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 16562 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 16562 T1363 C87 P53274 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 16562 T1363 C87 P53274 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 16563 T1363 C87 P53274 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 16564 T1363 C87 P53274 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 16564 T1363 C87 P53274 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 16565 T1363 C87 P53274 oass.SolrIndexSearcher.<init> Opening Searcher@306d09 main
[junit4:junit4] 2> 16566 T1362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@306d09 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 16566 T1363 C87 P53274 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@9a1ffa lockFactory=org.apache.lucene.store.NativeFSLockFactory@1aa5d39)
[junit4:junit4] 2> 16566 T1363 C87 P53274 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 16567 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 16567 T1363 C87 P53274 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 16567 T1363 C87 P53274 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16568 T1363 C87 P53274 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 17404 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17405 T1325 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:59906_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59906/valc/hl"}
[junit4:junit4] 2> 17410 T1325 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:53274_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53274/valc/hl"}
[junit4:junit4] 2> 17503 T1302 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49627_valc%2Fhl
[junit4:junit4] 2> 17506 T1307 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d67aa008b000c type:delete cxid:0xb zxid:0x9a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49627_valc%2Fhl Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49627_valc%2Fhl
[junit4:junit4] 2> 17507 T1302 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49627_valc%2Fhl
[junit4:junit4] 2> 17508 T1394 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> 17509 T1331 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> 17509 T1377 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> 17509 T1344 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> 17509 T1360 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> 17509 T1324 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> 17511 T1331 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> 17511 T1344 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> 17512 T1377 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17512 T1360 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> 17512 T1377 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> 17512 T1394 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17513 T1344 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17514 T1331 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17514 T1360 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17517 T1397 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/collection1
[junit4:junit4] 2> 17518 T1397 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 17518 T1324 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17519 T1397 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 17519 T1324 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> 17519 T1397 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 17520 T1397 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/collection1/'
[junit4:junit4] 2> 17521 T1397 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/collection1/lib/README' to classloader
[junit4:junit4] 2> 17521 T1397 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 17565 T1397 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 17618 T1397 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 17624 T1397 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 17628 T1397 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 18039 T1397 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 18048 T1397 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 18051 T1397 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 18060 T1397 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18064 T1397 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18069 T1397 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18070 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18070 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 18070 T1397 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18071 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18071 T1397 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 18072 T1397 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 18072 T1397 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363243843616/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4/
[junit4:junit4] 2> 18072 T1397 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c7a1e5
[junit4:junit4] 2> 18073 T1397 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 18073 T1397 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4 forceNew: false
[junit4:junit4] 2> 18074 T1397 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4/index/
[junit4:junit4] 2> 18074 T1397 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 18074 T1397 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4/index forceNew: false
[junit4:junit4] 2> 18076 T1397 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 18076 T1397 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 18078 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 18078 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 18079 T1397 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 18079 T1397 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 18080 T1397 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 18080 T1397 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 18080 T1397 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 18081 T1397 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 18081 T1397 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 18084 T1397 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 18088 T1397 oass.SolrIndexSearcher.<init> Opening Searcher@19197b6 main
[junit4:junit4] 2> 18088 T1397 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4/tlog
[junit4:junit4] 2> 18089 T1397 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 18089 T1397 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 18095 T1398 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19197b6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 18097 T1397 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 18097 T1397 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18284 T1337 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=4&state=recovering&nodeName=127.0.0.1:59906_valc%252Fhl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2000
[junit4:junit4] 2> 19019 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19020 T1325 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:49627_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49627/valc/hl"}
[junit4:junit4] 2> 19020 T1325 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 19020 T1325 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 19143 T1344 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> 19143 T1360 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> 19143 T1331 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> 19143 T1377 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> 19143 T1394 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> 19143 T1324 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> 20102 T1397 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 20102 T1397 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49627/valc/hl collection:collection1 shard:shard1
[junit4:junit4] 2> 20105 T1397 oasc.ZkController.register We are http://127.0.0.1:49627/valc/hl/collection1/ and leader is http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 20105 T1397 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49627/valc/hl
[junit4:junit4] 2> 20106 T1397 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 20106 T1397 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C90 name=collection1 org.apache.solr.core.SolrCore@1af7242 url=http://127.0.0.1:49627/valc/hl/collection1 node=127.0.0.1:49627_valc%2Fhl C90_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49627_valc%2Fhl, base_url=http://127.0.0.1:49627/valc/hl}
[junit4:junit4] 2> 20107 T1399 C90 P49627 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 20107 T1397 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20107 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 20108 T1399 C90 P49627 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 20108 T1399 C90 P49627 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 20108 T1302 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 20109 T1302 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 20109 T1399 C90 P49627 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 20110 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 20114 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20115 T1302 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 20116 T1302 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 20117 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C88_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59906_valc%2Fhl, base_url=http://127.0.0.1:59906/valc/hl}
[junit4:junit4] 2> 20285 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42619/valc/hl/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 20285 T1380 C88 P59906 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59906/valc/hl START replicas=[http://127.0.0.1:42619/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 20286 T1380 C88 P59906 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 20286 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 20286 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 20287 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 20287 T1380 C88 P59906 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 20287 T1380 C88 P59906 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42619/valc/hl/collection1/. core=collection1
[junit4:junit4] 2> 20287 T1380 C88 P59906 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 20288 T1339 C89 P42619 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 20292 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20292 T1340 C89 P42619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 20293 T1340 C89 P42619 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 20293 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20293 T1340 C89 P42619 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 1
[junit4:junit4] 2> 20294 T1380 C88 P59906 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 20294 T1380 C88 P59906 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 20296 T1339 C89 P42619 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 20297 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 20297 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 20297 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 20300 T1340 C89 P42619 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0
[junit4:junit4] 2> 20301 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 20301 T1380 C88 P59906 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty3/index.20130314095047632 forceNew: false
[junit4:junit4] 2> 20302 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@50f1bb lockFactory=org.apache.lucene.store.NativeFSLockFactory@1895677) fullCopy=false
[junit4:junit4] 2> 20304 T1337 C89 P42619 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=1
[junit4:junit4] 2> 20305 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 20313 T1380 C88 P59906 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 20313 T1380 C88 P59906 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 20314 T1380 C88 P59906 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 20315 T1380 C88 P59906 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 20315 T1380 C88 P59906 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 20315 T1380 C88 P59906 oass.SolrIndexSearcher.<init> Opening Searcher@1a9276a main
[junit4:junit4] 2> 20317 T1379 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a9276a main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 20317 T1380 C88 P59906 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@50f1bb lockFactory=org.apache.lucene.store.NativeFSLockFactory@1895677)
[junit4:junit4] 2> 20317 T1380 C88 P59906 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 20317 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 20318 T1380 C88 P59906 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 20318 T1380 C88 P59906 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 20319 T1380 C88 P59906 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 20648 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20648 T1325 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:49627_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49627/valc/hl"}
[junit4:junit4] 2> 20651 T1325 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:59906_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59906/valc/hl"}
[junit4:junit4] 2> 20753 T1344 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> 20753 T1360 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> 20754 T1331 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> 20753 T1324 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> 20753 T1394 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> 20753 T1377 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> 21114 T1338 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=5&state=recovering&nodeName=127.0.0.1:49627_valc%252Fhl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 21118 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22120 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C90_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49627_valc%2Fhl, base_url=http://127.0.0.1:49627/valc/hl}
[junit4:junit4] 2> 23115 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:42619/valc/hl/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 23115 T1399 C90 P49627 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49627/valc/hl START replicas=[http://127.0.0.1:42619/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 23115 T1399 C90 P49627 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 23116 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 23116 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 23116 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 23116 T1399 C90 P49627 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 23116 T1399 C90 P49627 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:42619/valc/hl/collection1/. core=collection1
[junit4:junit4] 2> 23116 T1399 C90 P49627 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 23117 T1339 C89 P42619 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 23119 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 23120 T1340 C89 P42619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 23121 T1340 C89 P42619 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 23121 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 23122 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23122 T1340 C89 P42619 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 23122 T1399 C90 P49627 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 23123 T1399 C90 P49627 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 23124 T1337 C89 P42619 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 23125 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 23125 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 23125 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 23127 T1339 C89 P42619 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 23127 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 23128 T1399 C90 P49627 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363243827336/jetty4/index.20130314095050458 forceNew: false
[junit4:junit4] 2> 23128 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ba9caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@a394ef) fullCopy=false
[junit4:junit4] 2> 23130 T1340 C89 P42619 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 23131 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 23131 T1399 C90 P49627 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 23131 T1399 C90 P49627 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 23132 T1399 C90 P49627 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 23133 T1399 C90 P49627 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 23133 T1399 C90 P49627 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 23133 T1399 C90 P49627 oass.SolrIndexSearcher.<init> Opening Searcher@5c9a1f main
[junit4:junit4] 2> 23134 T1398 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c9a1f main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 23135 T1399 C90 P49627 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ba9caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@a394ef)
[junit4:junit4] 2> 23135 T1399 C90 P49627 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 23135 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 23135 T1399 C90 P49627 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 23135 T1399 C90 P49627 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 23136 T1399 C90 P49627 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 23762 T1325 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23762 T1325 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:49627_valc%2Fhl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49627/valc/hl"}
[junit4:junit4] 2> 23765 T1394 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> 23765 T1360 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> 23765 T1377 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> 23765 T1324 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> 23765 T1344 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> 23765 T1331 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> 24123 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 24124 T1302 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C91 name=collection1 org.apache.solr.core.SolrCore@107f51 url=http://127.0.0.1:49352/valc/hl/collection1 node=127.0.0.1:49352_valc%2Fhl C91_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49352_valc%2Fhl, base_url=http://127.0.0.1:49352/valc/hl, leader=true}
[junit4:junit4] 2> 24129 T1320 C91 P49352 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24130 T1320 C91 P49352 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@162c83f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c8bca6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 24130 T1320 C91 P49352 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 24131 T1320 C91 P49352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@162c83f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c8bca6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@162c83f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c8bca6),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 24132 T1320 C91 P49352 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 24132 T1320 C91 P49352 oass.SolrIndexSearcher.<init> Opening Searcher@1892f6c main
[junit4:junit4] 2> 24132 T1320 C91 P49352 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24133 T1328 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1892f6c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 24133 T1320 C91 P49352 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 24137 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24137 T1340 C89 P42619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 24138 T1340 C89 P42619 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 24138 T1340 C89 P42619 oass.SolrIndexSearcher.<init> Opening Searcher@1f1ebd9 main
[junit4:junit4] 2> 24138 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24139 T1346 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f1ebd9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 24139 T1340 C89 P42619 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:53274/valc/hl/collection1/, StdNode: http://127.0.0.1:59906/valc/hl/collection1/, StdNode: http://127.0.0.1:49627/valc/hl/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C90_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49627_valc%2Fhl, base_url=http://127.0.0.1:49627/valc/hl}
[junit4:junit4] 2> 24147 T1387 C90 P49627 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C87_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53274_valc%2Fhl, base_url=http://127.0.0.1:53274/valc/hl}
[junit4:junit4] 2> 24147 T1354 C87 P53274 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C88_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59906_valc%2Fhl, base_url=http://127.0.0.1:59906/valc/hl}
[junit4:junit4] 2> 24147 T1370 C88 P59906 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24148 T1387 C90 P49627 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 24149 T1354 C87 P53274 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 24149 T1387 C90 P49627 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 24150 T1354 C87 P53274 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 24149 T1370 C88 P59906 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 24150 T1387 C90 P49627 oass.SolrIndexSearcher.<init> Opening Searcher@665ee7 main
[junit4:junit4] 2> 24150 T1354 C87 P53274 oass.SolrIndexSearcher.<init> Opening Searcher@485b81 main
[junit4:junit4] 2> 24151 T1370 C88 P59906 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 24151 T1354 C87 P53274 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24151 T1370 C88 P59906 oass.SolrIndexSearcher.<init> Opening Searcher@1d4fb82 main
[junit4:junit4] 2> 24151 T1387 C90 P49627 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24151 T1398 oasc.JmxMonitoredMap.put WARNING Failed to register info bean: searcher javax.management.InstanceNotFoundException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1095)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:427)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:537)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:138)
[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> 24152 T1362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@485b81 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 24152 T1370 C88 P59906 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24152 T1379 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d4fb82 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 24152 T1354 C87 P53274 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 24153 T1398 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@665ee7 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 24153 T1370 C88 P59906 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 24153 T1387 C90 P49627 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 24154 T1340 C89 P42619 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 2> 24154 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 24156 T1337 C89 P42619 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 24158 T1353 C87 P53274 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 24159 T1371 C88 P59906 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 24160 T1388 C90 P49627 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 26164 T1317 C91 P49352 oass.SolrIndexSearcher.<init> Opening Searcher@cc500c realtime
[junit4:junit4] 2> 26164 T1317 C91 P49352 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1429464786921324544)} 0 2
[junit4:junit4] 2> 26170 T1370 C88 P59906 /update {update.distrib=FROMLEADER&_version_=-1429464786924470272&update.from=http://127.0.0.1:42619/valc/hl/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429464786924470272)} 0 1
[junit4:junit4] 2> 26170 T1353 C87 P53274 /update {update.distrib=FROMLEADER&_version_=-1429464786924470272&update.from=http://127.0.0.1:42619/valc/hl/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429464786924470272)} 0 1
[junit4:junit4] 2> 26170 T1387 C90 P49627 /update {update.distrib=FROMLEADER&_version_=-1429464786924470272&update.from=http://127.0.0.1:42619/valc/hl/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429464786924470272)} 0 1
[junit4:junit4] 2> 26170 T1337 C89 P42619 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1429464786924470272)} 0 4
[junit4:junit4] 2> 26174 T1318 C91 P49352 /update {wt=javabin&version=2} {add=[0 (1429464786930761728)]} 0 2
[junit4:junit4] 2> 26180 T1356 C87 P53274 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429464786934956032)]} 0 2
[junit4:junit4] 2> 26181 T1389 C90 P49627 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429464786934956032)]} 0 2
[junit4:junit4] 2> 26181 T1371 C88 P59906 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429464786934956032)]} 0 3
[junit4:junit4] 2> 26182 T1340 C89 P42619 /update {wt=javabin&version=2} {add=[0 (1429464786934956032)]} 0 6
[junit4:junit4] 2> 26184 T1319 C91 P49352 /update {wt=javabin&version=2} {add=[1 (1429464786943344640)]} 0 0
[junit4:junit4] 2> 26189 T1372 C88 P59906 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429464786945441792)]} 0 1
[junit4:junit4] 2> 26190 T1355 C87 P53274 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429464786945441792)]} 0 2
[junit4:junit4] 2> 26189 T1390 C90 P49627 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429464786945441792)]} 0 1
[junit4:junit4] 2> 26190 T1338 C89 P42619 /update {wt=javabin&version=2} {add=[1 (1429464786945441792)]} 0 4
[junit4:junit4] 2> 26193 T1320 C91 P49352 /update {wt=javabin&version=2} {add=[2 (1429464786951733248)]} 0 1
[junit4:junit4] 2> 26197 T1373 C88 P59906 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1429464786954878976)]} 0 0
[junit4:junit4] 2> 26197 T1388 C90 P49627 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1429464786954878976)]} 0 0
[junit4:junit4] 2> 26198 T1339 C89 P42619 /update {test.distrib.skip.servers=http://127.0.0.1:53274/valc/hl/collection1/&wt=javabin&version=2} {add=[2 (1429464786954878976)]} 0 3
[junit4:junit4] 2> 26201 T1317 C91 P49352 /update {wt=javabin&version=2} {add=[3 (1429464786960121856)]} 0 1
[junit4:junit4] 2> 26205 T1387 C90 P49627 /update {distrib.from=http://127.0.0.1:42619/valc/hl/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1429464786963267584)]} 0 0
[junit4:junit4] 2> 26206 T1337 C89 P42619 /update {test.distrib.skip.servers=http://127.0.0.1:53274/valc/hl/collection1/&test.distrib.skip.servers=http://127.0.0.1:59906/valc/hl/collection1/&wt=javabin&version=2} {add=[3 (1429464786963267584)]} 0 4
[junit4:junit4] 2> 26208 T1318 C91 P49352 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26210 T1318 C91 P49352 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@162c83f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c8bca6),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@162c83f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c8bca6),segFN=segments_3,generation=3,filenames=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip, segments_3]
[junit4:junit4] 2> 26211 T1318 C91 P49352 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip, segments_3]
[junit4:junit4] 2> 26212 T1318 C91 P49352 oass.SolrIndexSearcher.<init> Opening Searcher@1a0f595 main
[junit4:junit4] 2> 26213 T1318 C91 P49352 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26213 T1328 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a0f595 main{StandardDirectoryReader(segments_3:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 26214 T1318 C91 P49352 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 26216 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26218 T1340 C89 P42619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=5
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1275bb8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ec409),segFN=segments_6,generation=6,filenames=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, segments_6, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 26218 T1340 C89 P42619 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, segments_6, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 26269 T1340 C89 P42619 oass.SolrIndexSearcher.<init> Opening Searcher@545ed6 main
[junit4:junit4] 2> 26270 T1340 C89 P42619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26271 T1346 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@545ed6 main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 26271 T1340 C89 P42619 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:53274/valc/hl/collection1/, StdNode: http://127.0.0.1:59906/valc/hl/collection1/, StdNode: http://127.0.0.1:49627/valc/hl/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 26273 T1354 C87 P53274 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26273 T1370 C88 P59906 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26273 T1389 C90 P49627 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26275 T1354 C87 P53274 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@177760a lockFactory=org.apache.lucene.store.NativeFSLockFactory@13aae39),segFN=segments_4,generation=4,filenames=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip, segments_4]
[junit4:junit4] 2> 26276 T1354 C87 P53274 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip, segments_4]
[junit4:junit4] 2> 26276 T1370 C88 P59906 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e45726 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d256a8),segFN=segments_5,generation=5,filenames=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, segments_5, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 26276 T1389 C90 P49627 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e7c97f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f41688),segFN=segments_6,generation=6,filenames=[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, segments_6, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 26277 T1354 C87 P53274 oass.SolrIndexSearcher.<init> Opening Searcher@12ed6ce main
[junit4:junit4] 2> 26277 T1370 C88 P59906 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, segments_5, _0_Lucene41_0.tim, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 26277 T1389 C90 P49627 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0.fnm, _0_Lucene41_0.doc, _0_Lucene41_0.pos, _0.nvd, _0.fdx, _0.si, _0.nvm, _0_Lucene41_0.tim, segments_6, _0.fdt, _0_Lucene41_0.tip]
[junit4:junit4] 2> 26277 T1354 C87 P53274 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26278 T1389 C90 P49627 oass.SolrIndexSearcher.<init> Opening Searcher@13b3e87 main
[junit4:junit4] 2> 26278 T1370 C88 P59906 oass.SolrIndexSearcher.<init> Opening Searcher@864f3f main
[junit4:junit4] 2> 26278 T1362 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12ed6ce main{StandardDirectoryReader(segments_4:3:nrt _0(4.3):C2)}
[junit4:junit4] 2> 26279 T1389 C90 P49627 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26279 T1370 C88 P59906 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26279 T1354 C87 P53274 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 26279 T1398 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13b3e87 main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 26280 T1379 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@864f3f main{StandardDirectoryReader(segments_5:3:nrt _0(4.3):C3)}
[junit4:junit4] 2> 26280 T1389 C90 P49627 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 26280 T1370 C88 P59906 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 26281 T1340 C89 P42619 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 65
[junit4:junit4] 2> 26282 T1302 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 26283 T1302 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 26283 T1302 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 26285 T1338 C89 P42619 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 26287 T1353 C87 P53274 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 26289 T1371 C88 P59906 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=0
[junit4:junit4] 2> 26291 T1390 C90 P49627 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 26293 T1302 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 26297 T1373 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 26297 T1373 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 26301 T1339 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 26301 T1339 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 26301 T1339 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl START replicas=[http://127.0.0.1:53274/valc/hl/collection1/, http://127.0.0.1:59906/valc/hl/collection1/, http://127.0.0.1:49627/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 26303 T1355 C87 P53274 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 26303 T1370 C88 P59906 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 26303 T1387 C90 P49627 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 26303 T1339 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl Received 3 versions from 127.0.0.1:53274/valc/hl/collection1/
[junit4:junit4] 2> 26304 T1339 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl Our versions are newer. ourLowThreshold=1429464786924470272 otherHigh=1429464786945441792
[junit4:junit4] 2> 26304 T1339 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl Received 4 versions from 127.0.0.1:59906/valc/hl/collection1/
[junit4:junit4] 2> 26304 T1339 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl Our versions are newer. ourLowThreshold=1429464786924470272 otherHigh=1429464786954878976
[junit4:junit4] 2> 26304 T1339 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl Received 5 versions from 127.0.0.1:49627/valc/hl/collection1/
[junit4:junit4] 2> 26305 T1339 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl Our versions are newer. ourLowThreshold=1429464786924470272 otherHigh=1429464786954878976
[junit4:junit4] 2> 26305 T1339 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42619/valc/hl DONE. sync succeeded
[junit4:junit4] 2> 26305 T1339 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 26306 T1339 oasc.SyncStrategy.syncToMe http://127.0.0.1:42619/valc/hl/collection1/: try and ask http://127.0.0.1:53274/valc/hl/collection1/ to sync
[junit4:junit4] 2> 26306 T1339 oasc.SyncStrategy.syncToMe http://127.0.0.1:42619/valc/hl/collection1/: try and ask http://127.0.0.1:59906/valc/hl/collection1/ to sync
[junit4:junit4] 2> 26306 T1339 oasc.SyncStrategy.syncToMe http://127.0.0.1:42619/valc/hl/collection1/: try and ask http://127.0.0.1:49627/valc/hl/collection1/ to sync
[junit4:junit4] 2> 26307 T1354 C87 P53274 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53274/valc/hl START replicas=[http://127.0.0.1:42619/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 26307 T1372 C88 P59906 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59906/valc/hl START replicas=[http://127.0.0.1:42619/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 26308 T1389 C90 P49627 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49627/valc/hl START replicas=[http://127.0.0.1:42619/valc/hl/collection1/] nUpdates=100
[junit4:junit4] 2> 26308 T1337 C89 P42619 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 26309 T1372 C88 P59906 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:59906/valc/hl Received 5 versions from 127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 26309 T1338 C89 P42619 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 26309 T1340 C89 P42619 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 26309 T1372 C88 P59906 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:59906/valc/hl Requesting updates from 127.0.0.1:42619/valc/hl/collection1/n=1 versions=[1429464786963267584]
[junit4:junit4] 2> 26310 T1354 C87 P53274 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:53274/valc/hl Received 5 versions from 127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 26309 T1389 C90 P49627 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:49627/valc/hl Received 5 versions from 127.0.0.1:42619/valc/hl/collection1/
[junit4:junit4] 2> 26310 T1354 C87 P53274 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:53274/valc/hl Requesting updates from 127.0.0.1:42619/valc/hl/collection1/n=2 versions=[1429464786963267584, 1429464786954878976]
[junit4:junit4] 2> 26310 T1389 C90 P49627 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:49627/valc/hl Our versions are newer. ourLowThreshold=1429464786924470272 otherHi
[...truncated too long message...]
ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=634BFEC70A0731B7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_MA -Dtests.timezone=Africa/Asmara -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 50.8s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([634BFEC70A0731B7:E2AD70DF7D58518B]: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> 50809 T1302 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 50813 T1301 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 50924 T1377 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 50924 T1377 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> 50924 T1377 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 50924 T1377 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 51669 T1305 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4] 2> 52011 T1394 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 52011 T1394 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> 52012 T1394 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 52012 T1394 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=HighCompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=373), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=373)), sim=DefaultSimilarity, locale=ar_MA, timezone=Africa/Asmara
[junit4:junit4] 2> NOTE: Linux 3.2.0-38-generic i386/Oracle Corporation 1.7.0_15 (32-bit)/cpus=8,threads=6,free=83144536,total=167403520
[junit4:junit4] 2> NOTE: All tests run in this JVM: [PeerSyncTest, CircularListTest, SolrTestCaseJ4Test, ReturnFieldsTest, TestFieldTypeResource, TermVectorComponentTest, TermsComponentTest, TestDynamicFieldResource, TestDynamicFieldCollectionResource, FileBasedSpellCheckerTest, TestCopyFieldCollectionResource, SuggesterFSTTest, ExternalFileFieldSortTest, SliceStateTest, ShowFileRequestHandlerTest, QueryParsingTest, TestFastLRUCache, TestBadConfig, CoreAdminHandlerTest, ResponseLogComponentTest, TestFastWriter, TestQueryUtils, SchemaVersionSpecificBehaviorTest, LoggingHandlerTest, StatelessScriptUpdateProcessorFactoryTest, TestReplicationHandler, TestValueSourceCache, TestRemoteStreaming, ZkControllerTest, CacheHeaderTest, ClusterStateUpdateTest, TestDocumentBuilder, UnloadDistributedZkTest, SolrIndexSplitterTest, RAMDirectoryFactoryTest, AlternateDirectoryTest, UUIDFieldTest, TestSolrIndexConfig, TestTrie, SOLR749Test, ChaosMonkeyNothingIsSafeTest, DistributedSpellCheckComponentTest, SimpleFacetsTest, TestLRUCache, FastVectorHighlighterTest, TestPseudoReturnFields, TestSolrQueryParser, DistributedQueryElevationComponentTest, BasicFunctionalityTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 52.09s, 1 test, 1 failure <<< FAILURES!
[...truncated 525 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: 56 minutes 20 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.7.0_15 -client -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure