You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/01/07 23:21:03 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java6 - Build # 15792 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java6/15792/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 should have just been set up to be inconsistent - but it's still consistent
Stack Trace:
java.lang.AssertionError: shard1 should have just been set up to be inconsistent - but it's still consistent
at __randomizedtesting.SeedInfo.seed([6D337706004B68C9:ECD5F91E771408F5]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertNotNull(Assert.java:526)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:214)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:794)
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:616)
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:679)
Build Log:
[...truncated 8273 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T813 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 3 T813 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1357596529484
[junit4:junit4] 2> 4 T813 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 5 T814 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 7 T814 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 7 T814 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 7 T814 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 8 T814 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 9 T814 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 106 T813 oasc.ZkTestServer.run start zk server on port:64418
[junit4:junit4] 2> 106 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3dd0b6f
[junit4:junit4] 2> 107 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 107 T819 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 108 T819 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 108 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64419
[junit4:junit4] 2> 108 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64419
[junit4:junit4] 2> 108 T817 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 111 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510000 with negotiated timeout 10000 for client /140.211.11.196:64419
[junit4:junit4] 2> 111 T819 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510000, negotiated timeout = 10000
[junit4:junit4] 2> 112 T820 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3dd0b6f name:ZooKeeperConnection Watcher:127.0.0.1:64418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 112 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 112 T813 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 114 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f13510000
[junit4:junit4] 2> 124 T820 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 124 T813 oaz.ZooKeeper.close Session: 0x13c170f13510000 closed
[junit4:junit4] 2> 124 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64419 which had sessionid 0x13c170f13510000
[junit4:junit4] 2> 124 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4786bc70
[junit4:junit4] 2> 125 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 125 T821 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 126 T821 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 126 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64420
[junit4:junit4] 2> 126 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64420
[junit4:junit4] 2> 127 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510001 with negotiated timeout 10000 for client /140.211.11.196:64420
[junit4:junit4] 2> 127 T821 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510001, negotiated timeout = 10000
[junit4:junit4] 2> 127 T822 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4786bc70 name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 128 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 128 T813 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 137 T813 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 139 T813 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 141 T813 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 143 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 143 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 147 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 148 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 251 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 252 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 254 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 254 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 256 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 257 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 265 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 265 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 267 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 268 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 275 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 275 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 277 T813 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 278 T813 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 279 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f13510001
[junit4:junit4] 2> 288 T822 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 288 T813 oaz.ZooKeeper.close Session: 0x13c170f13510001 closed
[junit4:junit4] 2> 288 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64420 which had sessionid 0x13c170f13510001
[junit4:junit4] 2> 399 T813 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 402 T813 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:64421
[junit4:junit4] 2> 402 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 402 T813 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 403 T813 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768
[junit4:junit4] 2> 403 T813 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/solr.xml
[junit4:junit4] 2> 403 T813 oasc.CoreContainer.<init> New CoreContainer 1215235052
[junit4:junit4] 2> 404 T813 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/'
[junit4:junit4] 2> 404 T813 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/'
[junit4:junit4] 2> 432 T813 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 433 T813 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 433 T813 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 433 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 433 T813 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 434 T813 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 434 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 434 T813 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 434 T813 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 435 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 449 T813 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 462 T813 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:64418/solr
[junit4:junit4] 2> 462 T813 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 463 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@6835449e
[junit4:junit4] 2> 463 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 464 T832 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 465 T832 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 465 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64422
[junit4:junit4] 2> 465 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64422
[junit4:junit4] 2> 467 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510002 with negotiated timeout 20000 for client /140.211.11.196:64422
[junit4:junit4] 2> 467 T832 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510002, negotiated timeout = 20000
[junit4:junit4] 2> 467 T833 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6835449e name:ZooKeeperConnection Watcher:127.0.0.1:64418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 467 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 468 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f13510002
[junit4:junit4] 2> 469 T833 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 469 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64422 which had sessionid 0x13c170f13510002
[junit4:junit4] 2> 469 T813 oaz.ZooKeeper.close Session: 0x13c170f13510002 closed
[junit4:junit4] 2> 469 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 478 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@a4dbd0f
[junit4:junit4] 2> 478 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 479 T834 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 479 T834 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 479 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64423
[junit4:junit4] 2> 479 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64423
[junit4:junit4] 2> 480 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510003 with negotiated timeout 20000 for client /140.211.11.196:64423
[junit4:junit4] 2> 480 T834 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510003, negotiated timeout = 20000
[junit4:junit4] 2> 481 T835 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a4dbd0f name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 481 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 482 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 491 T813 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 493 T813 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64421_
[junit4:junit4] 2> 493 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:delete cxid:0x7 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:64421_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:64421_
[junit4:junit4] 2> 500 T813 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64421_
[junit4:junit4] 2> 502 T813 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 575 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:delete cxid:0x15 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 577 T813 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 602 T813 oasc.Overseer.start Overseer (id=88971446156591107-127.0.0.1:64421_-n_0000000000) starting
[junit4:junit4] 2> 603 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x1a zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 604 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x1b zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 643 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x1c zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 644 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x1d zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 672 T837 oasc.OverseerCollectionProcessor.run Process current queue of collection messages
[junit4:junit4] 2> 672 T813 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 734 T813 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 736 T836 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 740 T838 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/collection1
[junit4:junit4] 2> 740 T838 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 740 T838 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 741 T838 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 741 T838 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/collection1/'
[junit4:junit4] 2> 742 T838 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 742 T838 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/collection1/lib/README' to classloader
[junit4:junit4] 2> 780 T838 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 831 T838 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 931 T838 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 935 T838 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1370 T838 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1377 T838 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1380 T838 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1392 T838 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1397 T838 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1402 T838 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1403 T838 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1404 T838 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357596529768/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data/
[junit4:junit4] 2> 1405 T838 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26b31b77
[junit4:junit4] 2> 1405 T838 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1433 T838 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data forceNew:false
[junit4:junit4] 2> 1433 T838 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data
[junit4:junit4] 2> 1433 T838 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data/index/
[junit4:junit4] 2> 1434 T838 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1435 T838 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data/index forceNew:false
[junit4:junit4] 2> 1447 T838 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5f2d8ca1; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1447 T838 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1448 T838 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data/index
[junit4:junit4] 2> 1448 T838 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 1449 T838 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1449 T838 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 1450 T838 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1450 T838 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 1450 T838 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1450 T838 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1451 T838 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1451 T838 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1451 T838 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1452 T838 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 1452 T838 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 1452 T838 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1453 T838 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 1453 T838 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 1453 T838 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 1453 T838 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1453 T838 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1454 T838 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1454 T838 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1454 T838 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1455 T838 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1455 T838 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1455 T838 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1456 T838 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1456 T838 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 1456 T838 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 1463 T838 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1467 T838 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 1468 T838 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 1470 T838 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/control/data
[junit4:junit4] 2> 1471 T838 oass.SolrIndexSearcher.<init> Opening Searcher@3f581b8c main
[junit4:junit4] 2> 1472 T838 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1472 T838 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1472 T838 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 1492 T838 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 1557 T839 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f581b8c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1560 T838 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1561 T838 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1561 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 2238 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2239 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64421_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64421"}
[junit4:junit4] 2> 2239 T836 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2239 T836 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2239 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 2262 T835 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> 2578 T838 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2578 T838 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64421 collection:control_collection shard:shard1
[junit4:junit4] 2> 2579 T838 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2602 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2603 T838 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2603 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2614 T838 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2614 T838 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2614 T838 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:64421/collection1/
[junit4:junit4] 2> 2614 T838 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2614 T838 oasc.SyncStrategy.syncToMe http://127.0.0.1:64421/collection1/ has no replicas
[junit4:junit4] 2> 2615 T838 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:64421/collection1/
[junit4:junit4] 2> 2615 T838 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2619 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3767 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3789 T835 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> 3800 T838 oasc.ZkController.register We are http://127.0.0.1:64421/collection1/ and leader is http://127.0.0.1:64421/collection1/
[junit4:junit4] 2> 3800 T838 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64421
[junit4:junit4] 2> 3800 T838 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3800 T838 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3800 T838 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3802 T838 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3803 T813 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3803 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3804 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3820 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3835 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@37db2007
[junit4:junit4] 2> 3836 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3836 T840 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3836 T840 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 3837 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64424
[junit4:junit4] 2> 3837 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64424
[junit4:junit4] 2> 3839 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510004 with negotiated timeout 10000 for client /140.211.11.196:64424
[junit4:junit4] 2> 3839 T840 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510004, negotiated timeout = 10000
[junit4:junit4] 2> 3839 T841 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37db2007 name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3839 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3840 T813 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3845 T813 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4026 T813 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4030 T813 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:64425
[junit4:junit4] 2> 4030 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4031 T813 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4031 T813 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325
[junit4:junit4] 2> 4031 T813 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/solr.xml
[junit4:junit4] 2> 4032 T813 oasc.CoreContainer.<init> New CoreContainer 1648134381
[junit4:junit4] 2> 4032 T813 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/'
[junit4:junit4] 2> 4033 T813 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/'
[junit4:junit4] 2> 4071 T813 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 4071 T813 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4071 T813 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4072 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4072 T813 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4072 T813 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4073 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4073 T813 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4073 T813 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4074 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4094 T813 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4110 T813 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:64418/solr
[junit4:junit4] 2> 4111 T813 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4111 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@50c94ac
[junit4:junit4] 2> 4112 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4113 T851 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4113 T851 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 4114 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64426
[junit4:junit4] 2> 4114 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64426
[junit4:junit4] 2> 4116 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510005 with negotiated timeout 20000 for client /140.211.11.196:64426
[junit4:junit4] 2> 4116 T851 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510005, negotiated timeout = 20000
[junit4:junit4] 2> 4116 T852 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50c94ac name:ZooKeeperConnection Watcher:127.0.0.1:64418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4116 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4117 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f13510005
[junit4:junit4] 2> 4130 T852 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4130 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64426 which had sessionid 0x13c170f13510005
[junit4:junit4] 2> 4130 T813 oaz.ZooKeeper.close Session: 0x13c170f13510005 closed
[junit4:junit4] 2> 4130 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 4138 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@c4888a7
[junit4:junit4] 2> 4139 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4139 T853 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4140 T853 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 4140 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64427
[junit4:junit4] 2> 4140 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64427
[junit4:junit4] 2> 4142 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510006 with negotiated timeout 20000 for client /140.211.11.196:64427
[junit4:junit4] 2> 4142 T853 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510006, negotiated timeout = 20000
[junit4:junit4] 2> 4142 T854 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c4888a7 name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4142 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4143 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4144 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4151 T813 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64425_
[junit4:junit4] 2> 4151 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510006 type:delete cxid:0x4 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:64425_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:64425_
[junit4:junit4] 2> 4152 T813 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64425_
[junit4:junit4] 2> 4159 T841 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4159 T835 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4159 T835 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> 4162 T813 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4166 T855 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/collection1
[junit4:junit4] 2> 4166 T855 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4167 T855 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4167 T855 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4168 T855 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/collection1/'
[junit4:junit4] 2> 4169 T855 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/collection1/lib/README' to classloader
[junit4:junit4] 2> 4169 T855 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4218 T855 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 4290 T855 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4391 T855 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4397 T855 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5020 T855 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5028 T855 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5031 T855 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5040 T855 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5043 T855 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5047 T855 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5047 T855 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5048 T855 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357596533325/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/
[junit4:junit4] 2> 5048 T855 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26b31b77
[junit4:junit4] 2> 5049 T855 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 5049 T855 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1 forceNew:false
[junit4:junit4] 2> 5050 T855 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 5050 T855 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index/
[junit4:junit4] 2> 5050 T855 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5051 T855 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index forceNew:false
[junit4:junit4] 2> 5066 T855 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5066 T855 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5067 T855 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index
[junit4:junit4] 2> 5067 T855 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 5069 T855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5069 T855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 5069 T855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5069 T855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 5070 T855 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5070 T855 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5070 T855 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5070 T855 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5071 T855 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5071 T855 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 5072 T855 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 5072 T855 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5072 T855 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 5072 T855 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 5073 T855 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 5073 T855 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5073 T855 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5074 T855 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5074 T855 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5074 T855 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5075 T855 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5075 T855 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5076 T855 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5076 T855 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 5076 T855 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 5077 T855 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 5082 T855 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5085 T855 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 5086 T855 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 5088 T855 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 5089 T855 oass.SolrIndexSearcher.<init> Opening Searcher@1c820671 main
[junit4:junit4] 2> 5090 T855 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5090 T855 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5090 T855 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 5103 T855 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 5189 T856 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c820671 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5194 T855 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5194 T855 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 5294 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5295 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64421_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64421"}
[junit4:junit4] 2> 5309 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64425_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64425"}
[junit4:junit4] 2> 5310 T836 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 5310 T836 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 5328 T835 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> 5328 T854 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> 5328 T841 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> 6197 T855 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6197 T855 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64425 collection:collection1 shard:shard1
[junit4:junit4] 2> 6198 T855 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 6215 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510006 type:delete cxid:0x43 zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 6216 T855 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 6216 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510006 type:create cxid:0x44 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6218 T855 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 6218 T855 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 6218 T855 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:64425/collection1/
[junit4:junit4] 2> 6218 T855 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 6218 T855 oasc.SyncStrategy.syncToMe http://127.0.0.1:64425/collection1/ has no replicas
[junit4:junit4] 2> 6219 T855 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:64425/collection1/
[junit4:junit4] 2> 6219 T855 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 6221 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510006 type:create cxid:0x4e zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6848 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6872 T854 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> 6872 T835 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> 6872 T841 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> 6888 T855 oasc.ZkController.register We are http://127.0.0.1:64425/collection1/ and leader is http://127.0.0.1:64425/collection1/
[junit4:junit4] 2> 6888 T855 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64425
[junit4:junit4] 2> 6888 T855 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 6888 T855 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 6889 T855 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6903 T855 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6904 T813 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 6904 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 6905 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 7092 T813 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 7095 T813 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:64443
[junit4:junit4] 2> 7096 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 7097 T813 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 7097 T813 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402
[junit4:junit4] 2> 7097 T813 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/solr.xml
[junit4:junit4] 2> 7098 T813 oasc.CoreContainer.<init> New CoreContainer 1044696854
[junit4:junit4] 2> 7098 T813 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/'
[junit4:junit4] 2> 7099 T813 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/'
[junit4:junit4] 2> 7140 T813 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 7141 T813 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 7141 T813 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 7142 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 7142 T813 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 7143 T813 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 7143 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 7143 T813 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 7144 T813 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 7144 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 7166 T813 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 7183 T813 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:64418/solr
[junit4:junit4] 2> 7184 T813 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 7184 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@741c42a9
[junit4:junit4] 2> 7185 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7186 T866 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 7187 T866 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 7187 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64444
[junit4:junit4] 2> 7187 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64444
[junit4:junit4] 2> 7189 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510007 with negotiated timeout 20000 for client /140.211.11.196:64444
[junit4:junit4] 2> 7189 T866 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510007, negotiated timeout = 20000
[junit4:junit4] 2> 7189 T867 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@741c42a9 name:ZooKeeperConnection Watcher:127.0.0.1:64418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7189 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7190 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f13510007
[junit4:junit4] 2> 7200 T867 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 7200 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64444 which had sessionid 0x13c170f13510007
[junit4:junit4] 2> 7200 T813 oaz.ZooKeeper.close Session: 0x13c170f13510007 closed
[junit4:junit4] 2> 7201 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 7213 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@6eed0e8a
[junit4:junit4] 2> 7214 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7215 T868 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 7215 T868 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 7215 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64446
[junit4:junit4] 2> 7215 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64446
[junit4:junit4] 2> 7216 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510008 with negotiated timeout 20000 for client /140.211.11.196:64446
[junit4:junit4] 2> 7217 T868 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510008, negotiated timeout = 20000
[junit4:junit4] 2> 7217 T869 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6eed0e8a name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7217 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7218 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7224 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510008 type:create cxid:0x2 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7225 T813 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64443_
[junit4:junit4] 2> 7226 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f13510008 type:delete cxid:0x4 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:64443_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:64443_
[junit4:junit4] 2> 7227 T813 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64443_
[junit4:junit4] 2> 7235 T835 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7236 T835 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> 7236 T854 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7236 T841 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7236 T854 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> 7236 T841 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> 7238 T813 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 7245 T870 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/collection1
[junit4:junit4] 2> 7245 T870 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 7246 T870 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 7246 T870 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 7247 T870 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/collection1/'
[junit4:junit4] 2> 7248 T870 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 7248 T870 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/collection1/lib/README' to classloader
[junit4:junit4] 2> 7282 T870 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 7328 T870 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 7429 T870 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 7433 T870 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 7860 T870 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 7868 T870 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 7871 T870 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 7883 T870 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 7886 T870 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 7889 T870 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 7890 T870 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 7891 T870 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357596536402/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/
[junit4:junit4] 2> 7891 T870 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26b31b77
[junit4:junit4] 2> 7891 T870 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 7892 T870 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2 forceNew:false
[junit4:junit4] 2> 7892 T870 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 7893 T870 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index/
[junit4:junit4] 2> 7893 T870 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 7894 T870 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index forceNew:false
[junit4:junit4] 2> 7899 T870 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3201ee4; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 7899 T870 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 7900 T870 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index
[junit4:junit4] 2> 7900 T870 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 7902 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 7902 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 7902 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 7902 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 7903 T870 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 7903 T870 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 7903 T870 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 7903 T870 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 7904 T870 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 7904 T870 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 7905 T870 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 7905 T870 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 7905 T870 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 7905 T870 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 7906 T870 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 7906 T870 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 7906 T870 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7907 T870 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7907 T870 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7907 T870 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7908 T870 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7908 T870 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7909 T870 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7909 T870 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 7909 T870 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 7910 T870 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 7914 T870 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 7917 T870 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 7918 T870 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 7920 T870 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 7921 T870 oass.SolrIndexSearcher.<init> Opening Searcher@14142f7e main
[junit4:junit4] 2> 7922 T870 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 7922 T870 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 7922 T870 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 7927 T870 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 7973 T871 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14142f7e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 7977 T870 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 7977 T870 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8404 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8405 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64425_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64425"}
[junit4:junit4] 2> 8408 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64443_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64443"}
[junit4:junit4] 2> 8408 T836 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 8408 T836 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 8422 T835 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> 8422 T854 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> 8422 T869 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> 8422 T841 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> 8984 T870 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 8984 T870 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64443 collection:collection1 shard:shard1
[junit4:junit4] 2> 8987 T870 oasc.ZkController.register We are http://127.0.0.1:64443/collection1/ and leader is http://127.0.0.1:64425/collection1/
[junit4:junit4] 2> 8988 T870 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64443
[junit4:junit4] 2> 8988 T870 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 8988 T870 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C18 name=collection1 org.apache.solr.core.SolrCore@77e6c94f url=http://127.0.0.1:64443/collection1 node=127.0.0.1:64443_ C18_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:64443_, base_url=http://127.0.0.1:64443}
[junit4:junit4] 2> 8995 T872 C18 P64443 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 8995 T870 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8996 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 8996 T872 C18 P64443 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 8996 T872 C18 P64443 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8996 T813 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 8997 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8997 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8999 T872 C18 P64443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 9157 T813 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 9159 T813 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:64456
[junit4:junit4] 2> 9160 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 9160 T813 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 9161 T813 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492
[junit4:junit4] 2> 9161 T813 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/solr.xml
[junit4:junit4] 2> 9161 T813 oasc.CoreContainer.<init> New CoreContainer 428279569
[junit4:junit4] 2> 9162 T813 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/'
[junit4:junit4] 2> 9162 T813 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/'
[junit4:junit4] 2> 9200 T813 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 9201 T813 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 9201 T813 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 9201 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 9202 T813 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 9202 T813 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 9202 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 9203 T813 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 9203 T813 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 9203 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 9222 T813 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 9238 T813 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:64418/solr
[junit4:junit4] 2> 9238 T813 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 9239 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1b491b64
[junit4:junit4] 2> 9240 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 9240 T882 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 9241 T882 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 9241 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64457
[junit4:junit4] 2> 9242 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64457
[junit4:junit4] 2> 9244 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f13510009 with negotiated timeout 20000 for client /140.211.11.196:64457
[junit4:junit4] 2> 9244 T882 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f13510009, negotiated timeout = 20000
[junit4:junit4] 2> 9244 T883 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b491b64 name:ZooKeeperConnection Watcher:127.0.0.1:64418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 9245 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 9246 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f13510009
[junit4:junit4] 2> 9252 T883 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 9252 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64457 which had sessionid 0x13c170f13510009
[junit4:junit4] 2> 9252 T813 oaz.ZooKeeper.close Session: 0x13c170f13510009 closed
[junit4:junit4] 2> 9252 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 9263 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3a9e7c70
[junit4:junit4] 2> 9264 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 9264 T884 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 9264 T884 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 9265 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64458
[junit4:junit4] 2> 9265 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64458
[junit4:junit4] 2> 9266 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f1351000a with negotiated timeout 20000 for client /140.211.11.196:64458
[junit4:junit4] 2> 9266 T884 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f1351000a, negotiated timeout = 20000
[junit4:junit4] 2> 9267 T885 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a9e7c70 name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 9267 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 9268 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f1351000a type:create cxid:0x1 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9269 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f1351000a type:create cxid:0x2 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9270 T813 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64456_
[junit4:junit4] 2> 9270 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f1351000a type:delete cxid:0x4 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:64456_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:64456_
[junit4:junit4] 2> 9279 T813 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64456_
[junit4:junit4] 2> 9281 T869 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> 9282 T841 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9282 T854 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9282 T835 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9282 T841 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> 9282 T854 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> 9282 T835 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> 9284 T869 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9285 T813 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9290 T886 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/collection1
[junit4:junit4] 2> 9291 T886 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9291 T886 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9291 T886 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9292 T886 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/collection1/'
[junit4:junit4] 2> 9294 T886 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/collection1/lib/README' to classloader
[junit4:junit4] 2> 9294 T886 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9345 T886 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9418 T886 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9518 T886 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9524 T886 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9927 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9928 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64443_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64443"}
[junit4:junit4] 2> 9945 T835 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> 9945 T885 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> 9945 T841 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> 9945 T854 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> 9945 T869 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> 10180 T886 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10193 T886 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10197 T886 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10210 T886 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10214 T886 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10219 T886 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10220 T886 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10221 T886 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357596538492/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/
[junit4:junit4] 2> 10221 T886 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26b31b77
[junit4:junit4] 2> 10221 T886 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 10222 T886 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3 forceNew:false
[junit4:junit4] 2> 10223 T886 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 10223 T886 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index/
[junit4:junit4] 2> 10224 T886 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10225 T886 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index forceNew:false
[junit4:junit4] 2> 10231 T886 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a80e05; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10232 T886 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10233 T886 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index
[junit4:junit4] 2> 10233 T886 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 10235 T886 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10235 T886 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 10236 T886 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10236 T886 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 10236 T886 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10237 T886 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10237 T886 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10238 T886 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10238 T886 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10239 T886 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 10239 T886 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 10240 T886 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10240 T886 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 10241 T886 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 10241 T886 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 10241 T886 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10242 T886 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10243 T886 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10243 T886 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10244 T886 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10244 T886 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10245 T886 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10245 T886 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10246 T886 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10246 T886 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 10247 T886 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 10255 T886 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10260 T886 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 10261 T886 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 10264 T886 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 10266 T886 oass.SolrIndexSearcher.<init> Opening Searcher@7c9aff86 main
[junit4:junit4] 2> 10267 T886 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10267 T886 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10267 T886 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 10275 T886 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 10339 T887 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c9aff86 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10344 T886 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10344 T886 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11449 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11450 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64456_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64456"}
[junit4:junit4] 2> 11450 T836 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11450 T836 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11462 T869 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> 11462 T841 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> 11462 T885 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> 11462 T854 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> 11462 T835 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> C18_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:64443_, base_url=http://127.0.0.1:64443}
[junit4:junit4] 2> 12043 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:64425/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 12049 T872 C18 P64443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 12065 T872 C18 P64443 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:64443 START replicas=[http://127.0.0.1:64425/collection1/] nUpdates=100
[junit4:junit4] 2> 12065 T872 C18 P64443 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 12066 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 12066 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 12067 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 12067 T872 C18 P64443 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 12067 T872 C18 P64443 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:64425/collection1/. core=collection1
[junit4:junit4] 2> 12067 T872 C18 P64443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C19 name=collection1 org.apache.solr.core.SolrCore@56882e24 url=http://127.0.0.1:64425/collection1 node=127.0.0.1:64425_ C19_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64425_, base_url=http://127.0.0.1:64425, leader=true}
[junit4:junit4] 2> 12076 T845 C19 P64425 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 12076 T846 C19 P64425 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 12077 T846 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 12082 T846 C19 P64425 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12082 T846 C19 P64425 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12087 T846 C19 P64425 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 12088 T846 C19 P64425 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 12089 T846 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 12089 T846 C19 P64425 oass.SolrIndexSearcher.<init> Opening Searcher@515fccae realtime
[junit4:junit4] 2> 12089 T846 C19 P64425 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 12089 T846 C19 P64425 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 12090 T872 C18 P64443 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 12091 T872 C18 P64443 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 12109 T872 C18 P64443 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 12112 T847 C19 P64425 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 12113 T847 C19 P64425 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 12114 T872 C18 P64443 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 12114 T872 C18 P64443 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 12114 T872 C18 P64443 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 12118 T847 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 12119 T847 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index
[junit4:junit4] 2> 12119 T847 C19 P64425 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2
[junit4:junit4] 2> 12120 T872 C18 P64443 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 12121 T872 C18 P64443 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601 forceNew:false
[junit4:junit4] 2> 12122 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12122 T872 C18 P64443 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601 lockFactory=org.apache.lucene.store.NativeFSLockFactory@363d2386; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 12135 T847 C19 P64425 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=6
[junit4:junit4] 2> 12148 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index
[junit4:junit4] 2> 12148 T872 C18 P64443 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 12149 T872 C18 P64443 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130108000901601
[junit4:junit4] 2> 12155 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12155 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12155 T872 C18 P64443 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601
[junit4:junit4] 2> 12158 T872 C18 P64443 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601 lockFactory=org.apache.lucene.store.NativeFSLockFactory@363d2386; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 12158 T872 C18 P64443 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 12159 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12162 T872 C18 P64443 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 12162 T872 C18 P64443 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 12162 T872 C18 P64443 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 12163 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601
[junit4:junit4] 2> 12163 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12165 T872 C18 P64443 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601 lockFactory=org.apache.lucene.store.NativeFSLockFactory@363d2386; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 12165 T872 C18 P64443 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 12166 T872 C18 P64443 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 12166 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12166 T872 C18 P64443 oass.SolrIndexSearcher.<init> Opening Searcher@2324fb16 main
[junit4:junit4] 2> 12167 T871 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2324fb16 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 12168 T871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index
[junit4:junit4] 2> 12168 T872 C18 P64443 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 12170 T872 C18 P64443 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601 lockFactory=org.apache.lucene.store.NativeFSLockFactory@363d2386; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601 lockFactory=org.apache.lucene.store.NativeFSLockFactory@363d2386; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 12170 T872 C18 P64443 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 12171 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2
[junit4:junit4] 2> 12171 T872 C18 P64443 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 12171 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index.20130108000901601
[junit4:junit4] 2> 12171 T872 C18 P64443 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty2/index
[junit4:junit4] 2> 12172 T872 C18 P64443 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 12172 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 12172 T872 C18 P64443 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 12172 T872 C18 P64443 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12181 T872 C18 P64443 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 12348 T886 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 12348 T886 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64456 collection:collection1 shard:shard1
[junit4:junit4] 2> 12351 T886 oasc.ZkController.register We are http://127.0.0.1:64456/collection1/ and leader is http://127.0.0.1:64425/collection1/
[junit4:junit4] 2> 12352 T886 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64456
[junit4:junit4] 2> 12352 T886 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 12352 T886 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C20 name=collection1 org.apache.solr.core.SolrCore@3f03033b url=http://127.0.0.1:64456/collection1 node=127.0.0.1:64456_ C20_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:64456_, base_url=http://127.0.0.1:64456}
[junit4:junit4] 2> 12352 T890 C20 P64456 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 12353 T886 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12353 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 12353 T890 C20 P64456 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 12353 T890 C20 P64456 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12354 T813 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 12354 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 12354 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12359 T890 C20 P64456 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12500 T813 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 12503 T813 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:64463
[junit4:junit4] 2> 12503 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 12503 T813 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 12504 T813 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847
[junit4:junit4] 2> 12504 T813 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/solr.xml
[junit4:junit4] 2> 12504 T813 oasc.CoreContainer.<init> New CoreContainer 857994437
[junit4:junit4] 2> 12505 T813 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/'
[junit4:junit4] 2> 12505 T813 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/'
[junit4:junit4] 2> 12543 T813 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 12544 T813 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 12544 T813 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 12544 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 12545 T813 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 12545 T813 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 12545 T813 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 12545 T813 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 12546 T813 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 12546 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 13137 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13138 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64443_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64443"}
[junit4:junit4] 2> 13140 T813 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 13154 T813 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:64418/solr
[junit4:junit4] 2> 13154 T813 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 13155 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@5c1d04ef
[junit4:junit4] 2> 13155 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13156 T900 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 13157 T900 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 13157 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64464
[junit4:junit4] 2> 13157 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64464
[junit4:junit4] 2> 13181 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f1351000b with negotiated timeout 20000 for client /140.211.11.196:64464
[junit4:junit4] 2> 13181 T900 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f1351000b, negotiated timeout = 20000
[junit4:junit4] 2> 13181 T901 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c1d04ef name:ZooKeeperConnection Watcher:127.0.0.1:64418 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13181 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13183 T818 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c170f1351000b
[junit4:junit4] 2> 13184 T901 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 13184 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64456_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64456"}
[junit4:junit4] 2> 13184 T813 oaz.ZooKeeper.close Session: 0x13c170f1351000b closed
[junit4:junit4] 2> 13184 T815 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:64464 which had sessionid 0x13c170f1351000b
[junit4:junit4] 2> 13185 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 13194 T813 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:64418/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@26efabf8
[junit4:junit4] 2> 13196 T813 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13196 T902 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 13196 T902 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:64418, initiating session
[junit4:junit4] 2> 13197 T815 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64465
[junit4:junit4] 2> 13197 T815 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64465
[junit4:junit4] 2> 13199 T817 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c170f1351000c with negotiated timeout 20000 for client /140.211.11.196:64465
[junit4:junit4] 2> 13199 T902 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:64418, sessionid = 0x13c170f1351000c, negotiated timeout = 20000
[junit4:junit4] 2> 13199 T903 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@26efabf8 name:ZooKeeperConnection Watcher:127.0.0.1:64418/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13200 T885 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> 13200 T854 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> 13200 T841 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> 13200 T835 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> 13200 T869 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> 13200 T813 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13201 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f1351000c type:create cxid:0x1 zxid:0x97 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13202 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f1351000c type:create cxid:0x2 zxid:0x99 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13211 T813 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64463_
[junit4:junit4] 2> 13212 T818 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c170f1351000c type:delete cxid:0x4 zxid:0x9b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:64463_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:64463_
[junit4:junit4] 2> 13213 T813 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64463_
[junit4:junit4] 2> 13221 T869 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> 13221 T835 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 13221 T841 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 13221 T885 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 13221 T854 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 13221 T841 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> 13221 T835 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> 13222 T854 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> 13221 T885 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> 13222 T869 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 13224 T813 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 13229 T904 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/collection1
[junit4:junit4] 2> 13229 T904 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 13230 T904 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 13230 T904 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 13231 T904 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/collection1/'
[junit4:junit4] 2> 13231 T904 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/collection1/lib/README' to classloader
[junit4:junit4] 2> 13232 T904 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 13268 T904 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 13317 T904 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13417 T904 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13423 T904 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13887 T904 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13894 T904 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13897 T904 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13907 T904 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13910 T904 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13913 T904 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13914 T904 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13914 T904 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357596541847/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/
[junit4:junit4] 2> 13915 T904 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26b31b77
[junit4:junit4] 2> 13915 T904 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 13916 T904 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4 forceNew:false
[junit4:junit4] 2> 13916 T904 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 13916 T904 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index/
[junit4:junit4] 2> 13917 T904 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13917 T904 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index forceNew:false
[junit4:junit4] 2> 13930 T904 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@35d356a0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13931 T904 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13931 T904 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index
[junit4:junit4] 2> 13932 T904 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 13933 T904 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13933 T904 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 13933 T904 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13934 T904 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 13934 T904 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13934 T904 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13934 T904 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13935 T904 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13935 T904 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13936 T904 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 13936 T904 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 13936 T904 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13937 T904 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 13937 T904 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 13937 T904 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 13937 T904 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13938 T904 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13938 T904 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13939 T904 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13939 T904 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13939 T904 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13940 T904 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13940 T904 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13940 T904 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 13941 T904 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 13941 T904 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 13946 T904 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13949 T904 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 13950 T904 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4] 2> 13951 T904 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 13953 T904 oass.SolrIndexSearcher.<init> Opening Searcher@307ca5b2 main
[junit4:junit4] 2> 13953 T904 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13953 T904 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13954 T904 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 13968 T904 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 14017 T905 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@307ca5b2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 14020 T904 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 14021 T904 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14715 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14716 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64463_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64463"}
[junit4:junit4] 2> 14716 T836 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 14716 T836 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 14728 T869 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> 14728 T885 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> 14728 T835 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> 14728 T841 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> 14728 T903 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> 14728 T854 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> 15023 T904 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 15023 T904 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64463 collection:collection1 shard:shard1
[junit4:junit4] 2> 15026 T904 oasc.ZkController.register We are http://127.0.0.1:64463/collection1/ and leader is http://127.0.0.1:64425/collection1/
[junit4:junit4] 2> 15026 T904 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64463
[junit4:junit4] 2> 15026 T904 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 15026 T904 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C21 name=collection1 org.apache.solr.core.SolrCore@c483f6c url=http://127.0.0.1:64463/collection1 node=127.0.0.1:64463_ C21_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:64463_, base_url=http://127.0.0.1:64463}
[junit4:junit4] 2> 15027 T906 C21 P64463 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 15027 T904 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15028 T906 C21 P64463 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 15028 T906 C21 P64463 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 15028 T906 C21 P64463 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15028 T813 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 15029 T813 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 15029 T813 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15031 T906 C21 P64463 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15046 T813 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15049 T813 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 15050 T813 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 15050 T813 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C20_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:64456_, base_url=http://127.0.0.1:64456}
[junit4:junit4] 2> 15371 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:64425/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15371 T890 C20 P64456 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:64456 START replicas=[http://127.0.0.1:64425/collection1/] nUpdates=100
[junit4:junit4] 2> 15372 T890 C20 P64456 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15372 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15373 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15373 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15373 T890 C20 P64456 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15373 T890 C20 P64456 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:64425/collection1/. core=collection1
[junit4:junit4] 2> 15373 T890 C20 P64456 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15375 T845 C19 P64425 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 15385 T850 C19 P64425 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15390 T850 C19 P64425 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15391 T850 C19 P64425 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15392 T850 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 15392 T850 C19 P64425 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15392 T850 C19 P64425 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 15394 T890 C20 P64456 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15394 T890 C20 P64456 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15398 T847 C19 P64425 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 15399 T890 C20 P64456 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 15399 T890 C20 P64456 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15399 T890 C20 P64456 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15401 T847 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 15402 T847 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index
[junit4:junit4] 2> 15402 T847 C19 P64425 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 15403 T890 C20 P64456 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15405 T890 C20 P64456 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884 forceNew:false
[junit4:junit4] 2> 15406 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15406 T890 C20 P64456 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@27c250e9; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 15411 T847 C19 P64425 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=1
[junit4:junit4] 2> 15413 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index
[junit4:junit4] 2> 15413 T890 C20 P64456 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15413 T890 C20 P64456 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130108000904884
[junit4:junit4] 2> 15415 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15415 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15416 T890 C20 P64456 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884
[junit4:junit4] 2> 15418 T890 C20 P64456 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@27c250e9; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15419 T890 C20 P64456 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15420 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15420 T890 C20 P64456 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15420 T890 C20 P64456 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15420 T890 C20 P64456 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 15421 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884
[junit4:junit4] 2> 15421 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15424 T890 C20 P64456 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@27c250e9; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15424 T890 C20 P64456 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15424 T890 C20 P64456 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15425 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15425 T890 C20 P64456 oass.SolrIndexSearcher.<init> Opening Searcher@61415858 main
[junit4:junit4] 2> 15427 T887 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@61415858 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 15427 T887 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index
[junit4:junit4] 2> 15429 T890 C20 P64456 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15432 T890 C20 P64456 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@27c250e9; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884 lockFactory=org.apache.lucene.store.NativeFSLockFactory@27c250e9; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 15432 T890 C20 P64456 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 15433 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3
[junit4:junit4] 2> 15433 T890 C20 P64456 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15433 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index.20130108000904884
[junit4:junit4] 2> 15433 T890 C20 P64456 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty3/index
[junit4:junit4] 2> 15433 T890 C20 P64456 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15433 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15434 T890 C20 P64456 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15434 T890 C20 P64456 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15442 T890 C20 P64456 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 16052 T813 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16231 T836 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16232 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64463_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64463"}
[junit4:junit4] 2> 16251 T836 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[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:64456_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64456"}
[junit4:junit4] 2> 16259 T885 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> 16259 T835 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> 16260 T903 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> 16260 T854 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> 16259 T841 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> 16259 T869 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> 17054 T813 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18056 T813 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C21_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:64463_, base_url=http://127.0.0.1:64463}
[junit4:junit4] 2> 19052 T906 C21 P64463 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:64425/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 19052 T906 C21 P64463 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:64463 START replicas=[http://127.0.0.1:64425/collection1/] nUpdates=100
[junit4:junit4] 2> 19053 T906 C21 P64463 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 19053 T906 C21 P64463 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 19053 T906 C21 P64463 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 19053 T906 C21 P64463 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 19053 T906 C21 P64463 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 19053 T906 C21 P64463 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:64425/collection1/. core=collection1
[junit4:junit4] 2> 19054 T906 C21 P64463 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19056 T845 C19 P64425 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 19058 T813 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19070 T844 C19 P64425 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 19088 T844 C19 P64425 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@451094e7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 19088 T844 C19 P64425 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 19089 T844 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 19089 T844 C19 P64425 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19090 T844 C19 P64425 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 19091 T906 C21 P64463 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19091 T906 C21 P64463 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 19095 T847 C19 P64425 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 19096 T906 C21 P64463 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 19096 T906 C21 P64463 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 19096 T906 C21 P64463 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 19098 T847 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1
[junit4:junit4] 2> 19099 T847 C19 P64425 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty1/index
[junit4:junit4] 2> 19099 T847 C19 P64425 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 19100 T906 C21 P64463 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 19104 T906 C21 P64463 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581 forceNew:false
[junit4:junit4] 2> 19105 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 19105 T906 C21 P64463 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581 lockFactory=org.apache.lucene.store.NativeFSLockFactory@424dfee; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 19110 T847 C19 P64425 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=1
[junit4:junit4] 2> 19111 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index
[junit4:junit4] 2> 19112 T906 C21 P64463 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 19112 T906 C21 P64463 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130108000908581
[junit4:junit4] 2> 19113 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 19114 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 19114 T906 C21 P64463 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581
[junit4:junit4] 2> 19118 T906 C21 P64463 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581 lockFactory=org.apache.lucene.store.NativeFSLockFactory@424dfee; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 19118 T906 C21 P64463 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 19120 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 19120 T906 C21 P64463 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 19120 T906 C21 P64463 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 19120 T906 C21 P64463 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 19121 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581
[junit4:junit4] 2> 19122 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 19125 T906 C21 P64463 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581 lockFactory=org.apache.lucene.store.NativeFSLockFactory@424dfee; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 19126 T906 C21 P64463 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 19126 T906 C21 P64463 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 19126 T906 C21 P64463 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 19127 T906 C21 P64463 oass.SolrIndexSearcher.<init> Opening Searcher@d900be1 main
[junit4:junit4] 2> 19128 T905 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d900be1 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 19129 T905 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index
[junit4:junit4] 2> 19129 T906 C21 P64463 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 19133 T906 C21 P64463 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index.20130108000908581 lockFactory=org.apache.lucene.store.NativeFSLockFactory@424dfee; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/w
[...truncated too long message...]
2> 145924 T813 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4
[junit4:junit4] 2> 145924 T813 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index
[junit4:junit4] 2> 145925 T813 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357596529484/jetty4/index
[junit4:junit4] 2> 146693 T902 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:64418. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 165441 T903 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 165441 T813 oaz.ZooKeeper.close Session: 0x13c170f1351000c closed
[junit4:junit4] 2> 165443 T813 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 165765 T813 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=6D337706004B68C9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=it -Dtests.timezone=Asia/Damascus -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 166s J1 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 should have just been set up to be inconsistent - but it's still consistent
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([6D337706004B68C9:ECD5F91E771408F5]:0)
[junit4:junit4] > at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4] > at org.junit.Assert.assertTrue(Assert.java:43)
[junit4:junit4] > at org.junit.Assert.assertNotNull(Assert.java:526)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:214)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:794)
[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:616)
[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:679)
[junit4:junit4] 2> 165784 T813 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41: {range_facet_l=PostingsFormat(name=Memory doPackFST= true), text=PostingsFormat(name=NestedPulsing), _version_=PostingsFormat(name=Memory doPackFST= true), rnd_b=PostingsFormat(name=Direct), intDefault=PostingsFormat(name=Memory doPackFST= true), id=PostingsFormat(name=Direct), timestamp=PostingsFormat(name=Memory doPackFST= true), a_t=PostingsFormat(name=Memory doPackFST= true), range_facet_sl=PostingsFormat(name=NestedPulsing), range_facet_si=Pulsing41(freqCutoff=18 minBlockSize=61 maxBlockSize=201), other_tl1=PostingsFormat(name=Memory doPackFST= true), multiDefault=Pulsing41(freqCutoff=18 minBlockSize=61 maxBlockSize=201), a_si=Pulsing41(freqCutoff=18 minBlockSize=61 maxBlockSize=201)}, sim=DefaultSimilarity, locale=it, timezone=Asia/Damascus
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=319592000,total=488898560
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SignatureUpdateProcessorFactoryTest, UpdateParamsTest, LukeRequestHandlerTest, TestBinaryField, RAMDirectoryFactoryTest, StandardRequestHandlerTest, QueryParsingTest, TestStressLucene, SynonymTokenizerTest, TestMultiCoreConfBootstrap, TestSolr4Spatial, TestAnalyzedSuggestions, DebugComponentTest, SolrCoreTest, SoftAutoCommitTest, DistributedQueryElevationComponentTest, BasicZkTest, TestZkChroot, TestLazyCores, FileUtilsTest, OverseerTest, TestWriterPerf, SyncSliceTest]
[junit4:junit4] Completed on J1 in 165.81s, 1 test, 1 failure <<< FAILURES!
[...truncated 502 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/build.xml:353: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build.xml:178: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/common-build.xml:428: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/lucene/common-build.xml:1176: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/lucene/common-build.xml:841: There were test failures: 246 suites, 1028 tests, 1 failure, 23 ignored (5 assumptions)
Total time: 34 minutes 16 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure