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/11 14:30:33 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1222 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1222/
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([988BD8961AC3177C:196D568E6D9C7740]: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 8641 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T3103 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_d/e
[junit4:junit4] 2> 4 T3103 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1357910861206
[junit4:junit4] 2> 5 T3103 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 6 T3104 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 9 T3104 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 9 T3104 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 9 T3104 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 9 T3104 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 10 T3104 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 107 T3103 oasc.ZkTestServer.run start zk server on port:40468
[junit4:junit4] 2> 107 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@52e46090
[junit4:junit4] 2> 108 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108 T3109 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 109 T3109 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 109 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:27303
[junit4:junit4] 2> 109 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:27303
[junit4:junit4] 2> 110 T3107 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 112 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0000 with negotiated timeout 10000 for client /140.211.11.196:27303
[junit4:junit4] 2> 112 T3109 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0000, negotiated timeout = 10000
[junit4:junit4] 2> 112 T3110 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52e46090 name:ZooKeeperConnection Watcher:127.0.0.1:40468 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 112 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 113 T3103 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 116 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c0000
[junit4:junit4] 2> 127 T3110 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 127 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:27303 which had sessionid 0x13c29cb659c0000
[junit4:junit4] 2> 127 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c0000 closed
[junit4:junit4] 2> 128 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@bd6113b
[junit4:junit4] 2> 129 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 129 T3111 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 129 T3111 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 129 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:48370
[junit4:junit4] 2> 130 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:48370
[junit4:junit4] 2> 131 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0001 with negotiated timeout 10000 for client /140.211.11.196:48370
[junit4:junit4] 2> 131 T3111 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0001, negotiated timeout = 10000
[junit4:junit4] 2> 131 T3112 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bd6113b name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 131 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 132 T3103 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 134 T3103 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 136 T3103 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 138 T3103 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 141 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 141 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 146 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 147 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 254 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 255 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 258 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 258 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 261 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 262 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 269 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 269 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 272 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 273 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 275 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 276 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 283 T3103 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 284 T3103 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 286 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c0001
[junit4:junit4] 2> 287 T3112 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 287 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c0001 closed
[junit4:junit4] 2> 287 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:48370 which had sessionid 0x13c29cb659c0001
[junit4:junit4] 2> 444 T3103 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 449 T3103 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:42610
[junit4:junit4] 2> 450 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 450 T3103 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 451 T3103 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489
[junit4:junit4] 2> 451 T3103 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/solr.xml
[junit4:junit4] 2> 452 T3103 oasc.CoreContainer.<init> New CoreContainer 1111400616
[junit4:junit4] 2> 452 T3103 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/'
[junit4:junit4] 2> 453 T3103 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/'
[junit4:junit4] 2> 494 T3103 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 494 T3103 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 495 T3103 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 495 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 496 T3103 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 496 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 497 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 497 T3103 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 498 T3103 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 498 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 518 T3103 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 536 T3103 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:40468/solr
[junit4:junit4] 2> 536 T3103 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 537 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@62820172
[junit4:junit4] 2> 538 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 538 T3122 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 539 T3122 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 539 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:38041
[junit4:junit4] 2> 539 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:38041
[junit4:junit4] 2> 541 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0002 with negotiated timeout 20000 for client /140.211.11.196:38041
[junit4:junit4] 2> 541 T3122 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0002, negotiated timeout = 20000
[junit4:junit4] 2> 541 T3123 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62820172 name:ZooKeeperConnection Watcher:127.0.0.1:40468 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 541 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 542 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c0002
[junit4:junit4] 2> 543 T3123 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 543 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:38041 which had sessionid 0x13c29cb659c0002
[junit4:junit4] 2> 543 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c0002 closed
[junit4:junit4] 2> 544 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 554 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@28e40e5c
[junit4:junit4] 2> 555 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 555 T3124 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 556 T3124 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 556 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:58014
[junit4:junit4] 2> 556 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:58014
[junit4:junit4] 2> 557 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0003 with negotiated timeout 20000 for client /140.211.11.196:58014
[junit4:junit4] 2> 558 T3124 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0003, negotiated timeout = 20000
[junit4:junit4] 2> 558 T3125 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28e40e5c name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 558 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 560 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 568 T3103 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 570 T3103 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42610__d%2Fe
[junit4:junit4] 2> 570 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:delete cxid:0x7 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:42610__d%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:42610__d%2Fe
[junit4:junit4] 2> 571 T3103 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42610__d%2Fe
[junit4:junit4] 2> 579 T3103 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 588 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 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> 595 T3103 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 598 T3103 oasc.Overseer.start Overseer (id=88992046200389635-127.0.0.1:42610__d%2Fe-n_0000000000) starting
[junit4:junit4] 2> 598 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x1a zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 600 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x1b zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 608 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x1c zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 609 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x1d zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 615 T3127 oasc.OverseerCollectionProcessor.run Process current queue of collection messages
[junit4:junit4] 2> 615 T3103 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 624 T3103 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 626 T3126 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 631 T3128 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/collection1
[junit4:junit4] 2> 631 T3128 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 631 T3128 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 632 T3128 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 633 T3128 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/collection1/'
[junit4:junit4] 2> 634 T3128 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 634 T3128 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/collection1/lib/README' to classloader
[junit4:junit4] 2> 685 T3128 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_41
[junit4:junit4] 2> 754 T3128 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 855 T3128 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 860 T3128 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1468 T3128 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1479 T3128 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1483 T3128 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1495 T3128 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1498 T3128 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1501 T3128 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1502 T3128 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1503 T3128 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1357910861489/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data/
[junit4:junit4] 2> 1503 T3128 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3d3b5a3a
[junit4:junit4] 2> 1503 T3128 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1504 T3128 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data forceNew:false
[junit4:junit4] 2> 1504 T3128 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data
[junit4:junit4] 2> 1504 T3128 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data/index/
[junit4:junit4] 2> 1505 T3128 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1506 T3128 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data/index forceNew:false
[junit4:junit4] 2> 1535 T3128 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16560927; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1535 T3128 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1536 T3128 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data/index
[junit4:junit4] 2> 1536 T3128 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 1537 T3128 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1537 T3128 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 1537 T3128 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1538 T3128 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 1538 T3128 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1538 T3128 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1538 T3128 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1539 T3128 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1539 T3128 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1539 T3128 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 1540 T3128 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 1540 T3128 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1540 T3128 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 1540 T3128 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 1540 T3128 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 1541 T3128 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1541 T3128 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1541 T3128 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1541 T3128 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1542 T3128 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1542 T3128 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1542 T3128 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1543 T3128 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1543 T3128 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 1543 T3128 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 1543 T3128 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 1548 T3128 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1551 T3128 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 1551 T3128 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> 1553 T3128 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/control/data
[junit4:junit4] 2> 1554 T3128 oass.SolrIndexSearcher.<init> Opening Searcher@554c2d03 main
[junit4:junit4] 2> 1555 T3128 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1555 T3128 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1555 T3128 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 1569 T3128 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 1614 T3129 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@554c2d03 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1616 T3128 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1616 T3128 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1617 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 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> 2129 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2129 T3126 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:42610__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42610/_d/e"}
[junit4:junit4] 2> 2130 T3126 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2130 T3126 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2130 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 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> 2145 T3125 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> 2629 T3128 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2629 T3128 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42610/_d/e collection:control_collection shard:shard1
[junit4:junit4] 2> 2630 T3128 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2651 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 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> 2658 T3128 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2658 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2661 T3128 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2661 T3128 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2661 T3128 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:42610/_d/e/collection1/
[junit4:junit4] 2> 2661 T3128 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2661 T3128 oasc.SyncStrategy.syncToMe http://127.0.0.1:42610/_d/e/collection1/ has no replicas
[junit4:junit4] 2> 2662 T3128 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:42610/_d/e/collection1/
[junit4:junit4] 2> 2662 T3128 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2670 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3657 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3677 T3125 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> 3693 T3128 oasc.ZkController.register We are http://127.0.0.1:42610/_d/e/collection1/ and leader is http://127.0.0.1:42610/_d/e/collection1/
[junit4:junit4] 2> 3693 T3128 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42610/_d/e
[junit4:junit4] 2> 3693 T3128 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3693 T3128 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3693 T3128 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3696 T3128 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3696 T3103 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3697 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3697 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3710 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3718 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4cff199e
[junit4:junit4] 2> 3719 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3720 T3130 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3720 T3130 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 3720 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:39524
[junit4:junit4] 2> 3721 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:39524
[junit4:junit4] 2> 3722 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0004 with negotiated timeout 10000 for client /140.211.11.196:39524
[junit4:junit4] 2> 3722 T3130 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0004, negotiated timeout = 10000
[junit4:junit4] 2> 3722 T3131 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cff199e name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3722 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3723 T3103 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3724 T3103 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3882 T3103 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3885 T3103 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:45418
[junit4:junit4] 2> 3886 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3886 T3103 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3887 T3103 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926
[junit4:junit4] 2> 3887 T3103 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/solr.xml
[junit4:junit4] 2> 3887 T3103 oasc.CoreContainer.<init> New CoreContainer 463113128
[junit4:junit4] 2> 3888 T3103 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/'
[junit4:junit4] 2> 3889 T3103 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/'
[junit4:junit4] 2> 3929 T3103 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 3930 T3103 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3930 T3103 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3931 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3931 T3103 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3932 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3932 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3932 T3103 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3933 T3103 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3933 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3951 T3103 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3969 T3103 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:40468/solr
[junit4:junit4] 2> 3969 T3103 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3970 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@42330db4
[junit4:junit4] 2> 3971 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3971 T3141 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3972 T3141 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 3972 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:56868
[junit4:junit4] 2> 3972 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:56868
[junit4:junit4] 2> 3974 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0005 with negotiated timeout 20000 for client /140.211.11.196:56868
[junit4:junit4] 2> 3974 T3141 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0005, negotiated timeout = 20000
[junit4:junit4] 2> 3974 T3142 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@42330db4 name:ZooKeeperConnection Watcher:127.0.0.1:40468 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3975 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3975 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c0005
[junit4:junit4] 2> 3985 T3142 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3985 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:56868 which had sessionid 0x13c29cb659c0005
[junit4:junit4] 2> 3985 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c0005 closed
[junit4:junit4] 2> 3986 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 3994 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@6117ae4e
[junit4:junit4] 2> 3995 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3995 T3143 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3996 T3143 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 3996 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:44042
[junit4:junit4] 2> 3996 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:44042
[junit4:junit4] 2> 3998 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0006 with negotiated timeout 20000 for client /140.211.11.196:44042
[junit4:junit4] 2> 3998 T3143 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0006, negotiated timeout = 20000
[junit4:junit4] 2> 3998 T3144 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6117ae4e name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3998 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3999 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4005 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4006 T3103 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45418__d%2Fe
[junit4:junit4] 2> 4007 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0006 type:delete cxid:0x4 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:45418__d%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:45418__d%2Fe
[junit4:junit4] 2> 4008 T3103 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45418__d%2Fe
[junit4:junit4] 2> 4016 T3131 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4016 T3125 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4016 T3125 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> 4018 T3103 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4024 T3145 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/collection1
[junit4:junit4] 2> 4025 T3145 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4025 T3145 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4025 T3145 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4026 T3145 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/collection1/'
[junit4:junit4] 2> 4028 T3145 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/collection1/lib/README' to classloader
[junit4:junit4] 2> 4028 T3145 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4078 T3145 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_41
[junit4:junit4] 2> 4147 T3145 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4247 T3145 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4252 T3145 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 4887 T3145 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 4898 T3145 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 4902 T3145 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 4914 T3145 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4918 T3145 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4922 T3145 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4923 T3145 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4924 T3145 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1357910864926/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/
[junit4:junit4] 2> 4924 T3145 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3d3b5a3a
[junit4:junit4] 2> 4925 T3145 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 4926 T3145 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1 forceNew:false
[junit4:junit4] 2> 4926 T3145 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 4927 T3145 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index/
[junit4:junit4] 2> 4927 T3145 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 4928 T3145 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index forceNew:false
[junit4:junit4] 2> 4934 T3145 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 4934 T3145 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 4935 T3145 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index
[junit4:junit4] 2> 4935 T3145 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 4937 T3145 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 4937 T3145 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 4937 T3145 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 4938 T3145 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 4938 T3145 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 4939 T3145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 4939 T3145 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 4939 T3145 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 4940 T3145 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 4940 T3145 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 4941 T3145 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 4941 T3145 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 4942 T3145 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 4942 T3145 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 4942 T3145 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 4943 T3145 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 4943 T3145 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4944 T3145 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4944 T3145 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4945 T3145 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4945 T3145 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4946 T3145 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4946 T3145 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4947 T3145 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 4947 T3145 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 4948 T3145 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 4955 T3145 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 4959 T3145 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 4960 T3145 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> 4962 T3145 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 4964 T3145 oass.SolrIndexSearcher.<init> Opening Searcher@7450fb7c main
[junit4:junit4] 2> 4965 T3145 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 4965 T3145 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 4966 T3145 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 4972 T3145 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 5028 T3146 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7450fb7c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5033 T3145 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5033 T3145 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 5189 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5189 T3126 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:42610__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42610/_d/e"}
[junit4:junit4] 2> 5193 T3126 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:45418__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45418/_d/e"}
[junit4:junit4] 2> 5193 T3126 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 5193 T3126 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 5204 T3144 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> 5204 T3125 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> 5205 T3131 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> 6035 T3145 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6035 T3145 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45418/_d/e collection:collection1 shard:shard1
[junit4:junit4] 2> 6036 T3145 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 6074 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0006 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> 6081 T3145 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 6082 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0006 type:create cxid:0x44 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6138 T3145 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 6138 T3145 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 6139 T3145 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:45418/_d/e/collection1/
[junit4:junit4] 2> 6139 T3145 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 6139 T3145 oasc.SyncStrategy.syncToMe http://127.0.0.1:45418/_d/e/collection1/ has no replicas
[junit4:junit4] 2> 6139 T3145 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:45418/_d/e/collection1/
[junit4:junit4] 2> 6139 T3145 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 6153 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0006 type:create cxid:0x4e zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6716 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6739 T3125 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> 6739 T3131 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> 6739 T3144 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> 6755 T3145 oasc.ZkController.register We are http://127.0.0.1:45418/_d/e/collection1/ and leader is http://127.0.0.1:45418/_d/e/collection1/
[junit4:junit4] 2> 6755 T3145 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45418/_d/e
[junit4:junit4] 2> 6755 T3145 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 6755 T3145 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 6755 T3145 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6757 T3145 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6758 T3103 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 6758 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 6759 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 6929 T3103 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 6932 T3103 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:25612
[junit4:junit4] 2> 6933 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 6933 T3103 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 6934 T3103 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973
[junit4:junit4] 2> 6934 T3103 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/solr.xml
[junit4:junit4] 2> 6934 T3103 oasc.CoreContainer.<init> New CoreContainer 1250732147
[junit4:junit4] 2> 6935 T3103 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/'
[junit4:junit4] 2> 6936 T3103 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/'
[junit4:junit4] 2> 6976 T3103 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 6977 T3103 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 6977 T3103 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 6978 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 6978 T3103 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 6979 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 6979 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 6979 T3103 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 6980 T3103 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 6980 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 7000 T3103 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 7018 T3103 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:40468/solr
[junit4:junit4] 2> 7018 T3103 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 7019 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1684fccf
[junit4:junit4] 2> 7020 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7020 T3156 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 7021 T3156 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 7021 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:42813
[junit4:junit4] 2> 7021 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:42813
[junit4:junit4] 2> 7023 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0007 with negotiated timeout 20000 for client /140.211.11.196:42813
[junit4:junit4] 2> 7023 T3156 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0007, negotiated timeout = 20000
[junit4:junit4] 2> 7024 T3157 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1684fccf name:ZooKeeperConnection Watcher:127.0.0.1:40468 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7024 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7025 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c0007
[junit4:junit4] 2> 7043 T3157 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 7043 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:42813 which had sessionid 0x13c29cb659c0007
[junit4:junit4] 2> 7043 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c0007 closed
[junit4:junit4] 2> 7044 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 7054 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@434ac1eb
[junit4:junit4] 2> 7055 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7055 T3158 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 7056 T3158 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 7056 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:53809
[junit4:junit4] 2> 7056 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:53809
[junit4:junit4] 2> 7057 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0008 with negotiated timeout 20000 for client /140.211.11.196:53809
[junit4:junit4] 2> 7058 T3158 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0008, negotiated timeout = 20000
[junit4:junit4] 2> 7058 T3159 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@434ac1eb name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7058 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7059 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7060 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0008 type:create cxid:0x2 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7062 T3103 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:25612__d%2Fe
[junit4:junit4] 2> 7062 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c0008 type:delete cxid:0x4 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:25612__d%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:25612__d%2Fe
[junit4:junit4] 2> 7070 T3103 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:25612__d%2Fe
[junit4:junit4] 2> 7073 T3131 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> 7073 T3125 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7074 T3144 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7074 T3125 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> 7074 T3144 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> 7076 T3131 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 7076 T3103 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 7084 T3160 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/collection1
[junit4:junit4] 2> 7084 T3160 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 7084 T3160 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 7085 T3160 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 7086 T3160 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/collection1/'
[junit4:junit4] 2> 7087 T3160 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 7087 T3160 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/collection1/lib/README' to classloader
[junit4:junit4] 2> 7150 T3160 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_41
[junit4:junit4] 2> 7225 T3160 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 7326 T3160 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 7332 T3160 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 7954 T3160 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 7966 T3160 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 7970 T3160 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 7984 T3160 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 7989 T3160 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 7993 T3160 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 7994 T3160 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 7996 T3160 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1357910867973/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/
[junit4:junit4] 2> 7996 T3160 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3d3b5a3a
[junit4:junit4] 2> 7996 T3160 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 7997 T3160 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2 forceNew:false
[junit4:junit4] 2> 7998 T3160 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 7998 T3160 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index/
[junit4:junit4] 2> 7999 T3160 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 7999 T3160 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index forceNew:false
[junit4:junit4] 2> 8005 T3160 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ee81fd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 8006 T3160 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 8007 T3160 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index
[junit4:junit4] 2> 8007 T3160 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 8008 T3160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 8009 T3160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 8009 T3160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 8009 T3160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 8010 T3160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 8010 T3160 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 8010 T3160 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 8011 T3160 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 8011 T3160 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 8012 T3160 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 8012 T3160 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 8013 T3160 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 8013 T3160 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 8013 T3160 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 8013 T3160 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 8014 T3160 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 8014 T3160 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8015 T3160 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8015 T3160 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8016 T3160 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8016 T3160 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8017 T3160 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8017 T3160 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8017 T3160 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 8018 T3160 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 8018 T3160 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 8026 T3160 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 8031 T3160 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 8032 T3160 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> 8034 T3160 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 8036 T3160 oass.SolrIndexSearcher.<init> Opening Searcher@57c6f1d9 main
[junit4:junit4] 2> 8037 T3160 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 8037 T3160 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 8037 T3160 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 8044 T3160 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 8208 T3161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@57c6f1d9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 8212 T3160 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 8213 T3160 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8252 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8253 T3126 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:45418__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45418/_d/e"}
[junit4:junit4] 2> 8257 T3126 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:25612__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:25612/_d/e"}
[junit4:junit4] 2> 8257 T3126 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 8257 T3126 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 8268 T3159 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> 8268 T3125 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> 8268 T3144 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> 8268 T3131 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> 9215 T3160 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 9215 T3160 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:25612/_d/e collection:collection1 shard:shard1
[junit4:junit4] 2> 9240 T3160 oasc.ZkController.register We are http://127.0.0.1:25612/_d/e/collection1/ and leader is http://127.0.0.1:45418/_d/e/collection1/
[junit4:junit4] 2> 9240 T3160 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:25612/_d/e
[junit4:junit4] 2> 9240 T3160 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 9240 T3160 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C175 name=collection1 org.apache.solr.core.SolrCore@7bae93c5 url=http://127.0.0.1:25612/_d/e/collection1 node=127.0.0.1:25612__d%2Fe C175_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:25612__d%2Fe, base_url=http://127.0.0.1:25612/_d/e}
[junit4:junit4] 2> 9241 T3162 C175 P25612 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 9241 T3160 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9241 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 9241 T3162 C175 P25612 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 9241 T3162 C175 P25612 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 9242 T3103 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 9242 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 9243 T3162 C175 P25612 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 9243 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 9418 T3103 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 9421 T3103 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:52398
[junit4:junit4] 2> 9422 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 9422 T3103 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 9423 T3103 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460
[junit4:junit4] 2> 9423 T3103 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/solr.xml
[junit4:junit4] 2> 9424 T3103 oasc.CoreContainer.<init> New CoreContainer 1549549505
[junit4:junit4] 2> 9425 T3103 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/'
[junit4:junit4] 2> 9425 T3103 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/'
[junit4:junit4] 2> 9466 T3103 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 9466 T3103 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 9467 T3103 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 9467 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 9468 T3103 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 9468 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 9469 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 9469 T3103 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 9469 T3103 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 9470 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 9490 T3103 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 9507 T3103 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:40468/solr
[junit4:junit4] 2> 9508 T3103 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 9508 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@40c5db6b
[junit4:junit4] 2> 9509 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 9510 T3172 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 9510 T3172 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 9511 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:24693
[junit4:junit4] 2> 9511 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:24693
[junit4:junit4] 2> 9513 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c0009 with negotiated timeout 20000 for client /140.211.11.196:24693
[junit4:junit4] 2> 9513 T3172 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c0009, negotiated timeout = 20000
[junit4:junit4] 2> 9513 T3173 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40c5db6b name:ZooKeeperConnection Watcher:127.0.0.1:40468 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 9513 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 9514 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c0009
[junit4:junit4] 2> 9523 T3173 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 9523 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:24693 which had sessionid 0x13c29cb659c0009
[junit4:junit4] 2> 9523 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c0009 closed
[junit4:junit4] 2> 9524 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 9535 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1db64d9f
[junit4:junit4] 2> 9536 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 9536 T3174 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 9537 T3174 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 9537 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63777
[junit4:junit4] 2> 9537 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63777
[junit4:junit4] 2> 9538 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c000a with negotiated timeout 20000 for client /140.211.11.196:63777
[junit4:junit4] 2> 9538 T3174 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c000a, negotiated timeout = 20000
[junit4:junit4] 2> 9539 T3175 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1db64d9f name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 9539 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 9540 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c000a type:create cxid:0x1 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9547 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c000a type:create cxid:0x2 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 9549 T3103 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52398__d%2Fe
[junit4:junit4] 2> 9549 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c000a type:delete cxid:0x4 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52398__d%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52398__d%2Fe
[junit4:junit4] 2> 9555 T3103 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52398__d%2Fe
[junit4:junit4] 2> 9557 T3159 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> 9557 T3131 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> 9558 T3125 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9558 T3144 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9558 T3125 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> 9558 T3144 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> 9558 T3159 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9559 T3131 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 9561 T3103 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9567 T3176 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/collection1
[junit4:junit4] 2> 9567 T3176 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9568 T3176 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9568 T3176 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9569 T3176 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/collection1/'
[junit4:junit4] 2> 9570 T3176 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9571 T3176 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/collection1/lib/README' to classloader
[junit4:junit4] 2> 9620 T3176 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_41
[junit4:junit4] 2> 9691 T3176 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9780 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9781 T3126 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:25612__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:25612/_d/e"}
[junit4:junit4] 2> 9792 T3176 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9794 T3175 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> 9794 T3144 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> 9794 T3131 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> 9794 T3125 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> 9794 T3159 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> 9798 T3176 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10387 T3176 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10398 T3176 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10402 T3176 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10414 T3176 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10418 T3176 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10422 T3176 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10423 T3176 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10424 T3176 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1357910870460/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/
[junit4:junit4] 2> 10424 T3176 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3d3b5a3a
[junit4:junit4] 2> 10425 T3176 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 10425 T3176 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3 forceNew:false
[junit4:junit4] 2> 10426 T3176 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 10426 T3176 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index/
[junit4:junit4] 2> 10427 T3176 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10428 T3176 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index forceNew:false
[junit4:junit4] 2> 10458 T3176 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6328ec5c; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10458 T3176 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10459 T3176 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index
[junit4:junit4] 2> 10460 T3176 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 10461 T3176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10462 T3176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 10462 T3176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10462 T3176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 10463 T3176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10463 T3176 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10463 T3176 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10464 T3176 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10464 T3176 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10465 T3176 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 10465 T3176 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 10466 T3176 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10466 T3176 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 10466 T3176 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 10467 T3176 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 10467 T3176 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10468 T3176 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10468 T3176 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10469 T3176 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10469 T3176 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10470 T3176 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10470 T3176 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10471 T3176 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10471 T3176 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 10471 T3176 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 10472 T3176 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 10479 T3176 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10483 T3176 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 10484 T3176 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> 10487 T3176 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 10488 T3176 oass.SolrIndexSearcher.<init> Opening Searcher@28871950 main
[junit4:junit4] 2> 10489 T3176 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10489 T3176 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10490 T3176 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 10507 T3176 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 10554 T3177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@28871950 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10559 T3176 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10559 T3176 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11298 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11299 T3126 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:52398__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52398/_d/e"}
[junit4:junit4] 2> 11299 T3126 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11299 T3126 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11324 T3125 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> 11324 T3159 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> 11324 T3175 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> 11324 T3131 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> 11324 T3144 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> 11561 T3176 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11561 T3176 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52398/_d/e collection:collection1 shard:shard1
[junit4:junit4] 2> 11564 T3176 oasc.ZkController.register We are http://127.0.0.1:52398/_d/e/collection1/ and leader is http://127.0.0.1:45418/_d/e/collection1/
[junit4:junit4] 2> 11564 T3176 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52398/_d/e
[junit4:junit4] 2> 11564 T3176 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11564 T3176 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C176 name=collection1 org.apache.solr.core.SolrCore@30ac1a39 url=http://127.0.0.1:52398/_d/e/collection1 node=127.0.0.1:52398__d%2Fe C176_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52398__d%2Fe, base_url=http://127.0.0.1:52398/_d/e}
[junit4:junit4] 2> 11565 T3178 C176 P52398 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11565 T3176 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11565 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11565 T3178 C176 P52398 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11566 T3178 C176 P52398 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11566 T3103 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 11566 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11567 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11569 T3178 C176 P52398 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11746 T3103 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11749 T3103 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:14070
[junit4:junit4] 2> 11749 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11750 T3103 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11750 T3103 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786
[junit4:junit4] 2> 11751 T3103 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/solr.xml
[junit4:junit4] 2> 11751 T3103 oasc.CoreContainer.<init> New CoreContainer 217183905
[junit4:junit4] 2> 11752 T3103 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/'
[junit4:junit4] 2> 11752 T3103 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/'
[junit4:junit4] 2> 11794 T3103 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4] 2> 11794 T3103 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11795 T3103 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11795 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11796 T3103 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11796 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11797 T3103 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11797 T3103 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11797 T3103 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11798 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11816 T3103 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11834 T3103 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:40468/solr
[junit4:junit4] 2> 11834 T3103 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11835 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3df390e3
[junit4:junit4] 2> 11836 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11836 T3188 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11837 T3188 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 11837 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:35483
[junit4:junit4] 2> 11837 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:35483
[junit4:junit4] 2> 11842 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c000b with negotiated timeout 20000 for client /140.211.11.196:35483
[junit4:junit4] 2> 11842 T3188 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c000b, negotiated timeout = 20000
[junit4:junit4] 2> 11842 T3189 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3df390e3 name:ZooKeeperConnection Watcher:127.0.0.1:40468 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11842 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11843 T3108 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13c29cb659c000b
[junit4:junit4] 2> 11854 T3189 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 11854 T3105 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:35483 which had sessionid 0x13c29cb659c000b
[junit4:junit4] 2> 11854 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c000b closed
[junit4:junit4] 2> 11854 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4] 2> 11863 T3103 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:40468/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@edf3c2a
[junit4:junit4] 2> 11864 T3103 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11864 T3190 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:40468. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11865 T3190 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:40468, initiating session
[junit4:junit4] 2> 11865 T3105 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:35891
[junit4:junit4] 2> 11865 T3105 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:35891
[junit4:junit4] 2> 11866 T3107 oazs.ZooKeeperServer.finishSessionInit Established session 0x13c29cb659c000c with negotiated timeout 20000 for client /140.211.11.196:35891
[junit4:junit4] 2> 11866 T3190 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:40468, sessionid = 0x13c29cb659c000c, negotiated timeout = 20000
[junit4:junit4] 2> 11867 T3191 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@edf3c2a name:ZooKeeperConnection Watcher:127.0.0.1:40468/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11867 T3103 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11868 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c000c type:create cxid:0x1 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11869 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c000c type:create cxid:0x2 zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11876 T3103 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:14070__d%2Fe
[junit4:junit4] 2> 11877 T3108 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13c29cb659c000c type:delete cxid:0x4 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:14070__d%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:14070__d%2Fe
[junit4:junit4] 2> 11878 T3103 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:14070__d%2Fe
[junit4:junit4] 2> 11880 T3159 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> 11880 T3131 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> 11880 T3175 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 11880 T3125 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 11880 T3144 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 11881 T3175 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> 11881 T3144 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> 11881 T3125 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> 11881 T3159 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 11881 T3131 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 11889 T3103 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 11895 T3192 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/collection1
[junit4:junit4] 2> 11896 T3192 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 11896 T3192 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 11896 T3192 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 11897 T3192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/collection1/'
[junit4:junit4] 2> 11898 T3192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/collection1/lib/README' to classloader
[junit4:junit4] 2> 11899 T3192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 11948 T3192 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_41
[junit4:junit4] 2> 12016 T3192 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 12117 T3192 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 12123 T3192 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> C175_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:25612__d%2Fe, base_url=http://127.0.0.1:25612/_d/e}
[junit4:junit4] 2> 12263 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:45418/_d/e/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 12263 T3162 C175 P25612 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:25612/_d/e START replicas=[http://127.0.0.1:45418/_d/e/collection1/] nUpdates=100
[junit4:junit4] 2> 12264 T3162 C175 P25612 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 12264 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 12264 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 12264 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 12264 T3162 C175 P25612 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 12265 T3162 C175 P25612 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:45418/_d/e/collection1/. core=collection1
[junit4:junit4] 2> 12265 T3162 C175 P25612 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C177 name=collection1 org.apache.solr.core.SolrCore@19b92512 url=http://127.0.0.1:45418/_d/e/collection1 node=127.0.0.1:45418__d%2Fe C177_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:45418__d%2Fe, base_url=http://127.0.0.1:45418/_d/e, leader=true}
[junit4:junit4] 2> 12272 T3136 C177 P45418 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 12274 T3137 C177 P45418 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 12276 T3137 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 12280 T3137 C177 P45418 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12281 T3137 C177 P45418 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12311 T3137 C177 P45418 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 12311 T3137 C177 P45418 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 12312 T3137 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 12313 T3137 C177 P45418 oass.SolrIndexSearcher.<init> Opening Searcher@72d638dc realtime
[junit4:junit4] 2> 12313 T3137 C177 P45418 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 12314 T3137 C177 P45418 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 40
[junit4:junit4] 2> 12314 T3162 C175 P25612 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 12315 T3162 C175 P25612 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 12316 T3138 C177 P45418 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 12316 T3138 C177 P45418 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 12317 T3162 C175 P25612 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 12317 T3162 C175 P25612 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 12317 T3162 C175 P25612 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 12319 T3138 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 12320 T3138 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index
[junit4:junit4] 2> 12320 T3138 C177 P45418 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 12321 T3162 C175 P25612 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 12322 T3162 C175 P25612 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522 forceNew:false
[junit4:junit4] 2> 12323 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12323 T3162 C175 P25612 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fd08d0; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 12327 T3138 C177 P45418 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 12328 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index
[junit4:junit4] 2> 12329 T3162 C175 P25612 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 12329 T3162 C175 P25612 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130111052753522
[junit4:junit4] 2> 12330 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12331 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12331 T3162 C175 P25612 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522
[junit4:junit4] 2> 12335 T3162 C175 P25612 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fd08d0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 12336 T3162 C175 P25612 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 12337 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12337 T3162 C175 P25612 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 12338 T3162 C175 P25612 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 12338 T3162 C175 P25612 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 12338 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522
[junit4:junit4] 2> 12339 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12343 T3162 C175 P25612 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fd08d0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 12344 T3162 C175 P25612 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 12344 T3162 C175 P25612 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 12344 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12345 T3162 C175 P25612 oass.SolrIndexSearcher.<init> Opening Searcher@54aa5c05 main
[junit4:junit4] 2> 12346 T3161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54aa5c05 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 12347 T3161 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index
[junit4:junit4] 2> 12347 T3162 C175 P25612 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 12351 T3162 C175 P25612 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fd08d0; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fd08d0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 12351 T3162 C175 P25612 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 12352 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2
[junit4:junit4] 2> 12353 T3162 C175 P25612 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 12353 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index.20130111052753522
[junit4:junit4] 2> 12353 T3162 C175 P25612 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty2/index
[junit4:junit4] 2> 12353 T3162 C175 P25612 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 12353 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 12353 T3162 C175 P25612 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 12354 T3162 C175 P25612 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12361 T3162 C175 P25612 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 12733 T3192 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 12744 T3192 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 12748 T3192 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 12760 T3192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 12769 T3192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 12773 T3192 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 12774 T3192 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 12775 T3192 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1357910872786/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/
[junit4:junit4] 2> 12775 T3192 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3d3b5a3a
[junit4:junit4] 2> 12776 T3192 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 12777 T3192 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4 forceNew:false
[junit4:junit4] 2> 12777 T3192 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 12778 T3192 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index/
[junit4:junit4] 2> 12778 T3192 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 12779 T3192 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index forceNew:false
[junit4:junit4] 2> 12785 T3192 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@72a9cbe4; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 12785 T3192 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 12786 T3192 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index
[junit4:junit4] 2> 12786 T3192 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4] 2> 12788 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 12788 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4] 2> 12788 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 12789 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4] 2> 12789 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 12789 T3192 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 12790 T3192 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 12790 T3192 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 12791 T3192 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 12791 T3192 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4] 2> 12792 T3192 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4] 2> 12792 T3192 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 12793 T3192 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4] 2> 12793 T3192 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4] 2> 12793 T3192 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4] 2> 12794 T3192 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 12794 T3192 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12795 T3192 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12795 T3192 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12796 T3192 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12796 T3192 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12797 T3192 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12797 T3192 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12797 T3192 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4] 2> 12798 T3192 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4] 2> 12798 T3192 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4] 2> 12805 T3192 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 12810 T3192 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4] 2> 12811 T3192 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> 12813 T3192 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 12815 T3192 oass.SolrIndexSearcher.<init> Opening Searcher@1092d44e main
[junit4:junit4] 2> 12816 T3192 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 12816 T3192 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 12816 T3192 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 12823 T3192 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 12880 T3195 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1092d44e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 12884 T3192 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 12885 T3192 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12918 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12918 T3126 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:52398__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52398/_d/e"}
[junit4:junit4] 2> 12922 T3126 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:25612__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:25612/_d/e"}
[junit4:junit4] 2> 12931 T3126 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:14070__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:14070/_d/e"}
[junit4:junit4] 2> 12931 T3126 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 12932 T3126 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 12942 T3125 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> 12942 T3191 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> 12942 T3131 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> 12942 T3144 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> 12942 T3175 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> 12942 T3159 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> 13887 T3192 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 13887 T3192 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:14070/_d/e collection:collection1 shard:shard1
[junit4:junit4] 2> 13891 T3192 oasc.ZkController.register We are http://127.0.0.1:14070/_d/e/collection1/ and leader is http://127.0.0.1:45418/_d/e/collection1/
[junit4:junit4] 2> 13891 T3192 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:14070/_d/e
[junit4:junit4] 2> 13891 T3192 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 13891 T3192 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C178 name=collection1 org.apache.solr.core.SolrCore@40de81f5 url=http://127.0.0.1:14070/_d/e/collection1 node=127.0.0.1:14070__d%2Fe C178_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:14070__d%2Fe, base_url=http://127.0.0.1:14070/_d/e}
[junit4:junit4] 2> 13892 T3196 C178 P14070 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 13892 T3192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13892 T3196 C178 P14070 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 13892 T3196 C178 P14070 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 13893 T3196 C178 P14070 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 13893 T3103 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 13893 T3103 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 13894 T3103 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13903 T3196 C178 P14070 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13908 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13909 T3103 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 13910 T3103 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 13910 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14455 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14456 T3126 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:14070__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:14070/_d/e"}
[junit4:junit4] 2> 14502 T3159 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> 14502 T3144 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> 14502 T3191 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> 14502 T3175 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> 14502 T3131 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> 14502 T3125 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> 14912 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C176_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52398__d%2Fe, base_url=http://127.0.0.1:52398/_d/e}
[junit4:junit4] 2> 15589 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:45418/_d/e/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15589 T3178 C176 P52398 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52398/_d/e START replicas=[http://127.0.0.1:45418/_d/e/collection1/] nUpdates=100
[junit4:junit4] 2> 15589 T3178 C176 P52398 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15590 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15590 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15590 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15590 T3178 C176 P52398 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15590 T3178 C176 P52398 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:45418/_d/e/collection1/. core=collection1
[junit4:junit4] 2> 15590 T3178 C176 P52398 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15592 T3136 C177 P45418 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 15600 T3140 C177 P45418 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15610 T3140 C177 P45418 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15610 T3140 C177 P45418 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15611 T3140 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 15611 T3140 C177 P45418 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15612 T3140 C177 P45418 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 15612 T3178 C176 P52398 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15613 T3178 C176 P52398 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15615 T3138 C177 P45418 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 15616 T3178 C176 P52398 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 15616 T3178 C176 P52398 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15616 T3178 C176 P52398 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15618 T3138 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 15619 T3138 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index
[junit4:junit4] 2> 15619 T3138 C177 P45418 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 15620 T3178 C176 P52398 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15621 T3178 C176 P52398 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821 forceNew:false
[junit4:junit4] 2> 15621 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15622 T3178 C176 P52398 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65443418; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 15625 T3138 C177 P45418 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 15626 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index
[junit4:junit4] 2> 15626 T3178 C176 P52398 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15627 T3178 C176 P52398 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130111052756821
[junit4:junit4] 2> 15628 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15628 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15629 T3178 C176 P52398 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821
[junit4:junit4] 2> 15632 T3178 C176 P52398 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65443418; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15632 T3178 C176 P52398 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15634 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15634 T3178 C176 P52398 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15634 T3178 C176 P52398 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15634 T3178 C176 P52398 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 15635 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821
[junit4:junit4] 2> 15636 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15639 T3178 C176 P52398 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65443418; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15639 T3178 C176 P52398 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15639 T3178 C176 P52398 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15640 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15640 T3178 C176 P52398 oass.SolrIndexSearcher.<init> Opening Searcher@3c6b2d27 main
[junit4:junit4] 2> 15641 T3177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3c6b2d27 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 15642 T3177 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index
[junit4:junit4] 2> 15642 T3178 C176 P52398 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15645 T3178 C176 P52398 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65443418; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65443418; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 15646 T3178 C176 P52398 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 15647 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3
[junit4:junit4] 2> 15647 T3178 C176 P52398 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15647 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index.20130111052756821
[junit4:junit4] 2> 15647 T3178 C176 P52398 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty3/index
[junit4:junit4] 2> 15647 T3178 C176 P52398 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15648 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15648 T3178 C176 P52398 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15648 T3178 C176 P52398 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15655 T3178 C176 P52398 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15914 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16006 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16007 T3126 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:52398__d%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52398/_d/e"}
[junit4:junit4] 2> 16057 T3175 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> 16057 T3159 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> 16057 T3191 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> 16057 T3131 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> 16057 T3125 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> 16057 T3144 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> C178_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:14070__d%2Fe, base_url=http://127.0.0.1:14070/_d/e}
[junit4:junit4] 2> 16915 T3196 C178 P14070 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:45418/_d/e/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 16915 T3196 C178 P14070 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:14070/_d/e START replicas=[http://127.0.0.1:45418/_d/e/collection1/] nUpdates=100
[junit4:junit4] 2> 16916 T3196 C178 P14070 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 16916 T3196 C178 P14070 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 16916 T3196 C178 P14070 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 16916 T3196 C178 P14070 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 16916 T3196 C178 P14070 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 16916 T3103 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16916 T3196 C178 P14070 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:45418/_d/e/collection1/. core=collection1
[junit4:junit4] 2> 16917 T3196 C178 P14070 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16918 T3136 C177 P45418 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 16936 T3134 C177 P45418 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 16949 T3134 C177 P45418 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@d570edd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 16950 T3134 C177 P45418 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 16951 T3134 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 16951 T3134 C177 P45418 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 16952 T3134 C177 P45418 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 16952 T3196 C178 P14070 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 16953 T3196 C178 P14070 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 16955 T3138 C177 P45418 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 16956 T3196 C178 P14070 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 16956 T3196 C178 P14070 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 16956 T3196 C178 P14070 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 16958 T3138 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1
[junit4:junit4] 2> 16959 T3138 C177 P45418 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty1/index
[junit4:junit4] 2> 16959 T3138 C177 P45418 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 16960 T3196 C178 P14070 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 16961 T3196 C178 P14070 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index.20130111052758161 forceNew:false
[junit4:junit4] 2> 16962 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 16962 T3196 C178 P14070 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index.20130111052758161 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71f7a8e3; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4] 2> 16966 T3138 C177 P45418 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 16967 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index
[junit4:junit4] 2> 16967 T3196 C178 P14070 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 16968 T3196 C178 P14070 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130111052758161
[junit4:junit4] 2> 16969 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 16970 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 16970 T3196 C178 P14070 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index.20130111052758161
[junit4:junit4] 2> 16974 T3196 C178 P14070 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index.20130111052758161 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71f7a8e3; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 16974 T3196 C178 P14070 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 16976 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 16976 T3196 C178 P14070 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 16976 T3196 C178 P14070 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 16976 T3196 C178 P14070 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 16977 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index.20130111052758161
[junit4:junit4] 2> 16978 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 16982 T3196 C178 P14070 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4/index.20130111052758161 lockFactory=org.apache.lucene.store.NativeFSLockFactory@71f7a8e3; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 16982 T3196 C178 P14070 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 16983 T3196 C178 P14070 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 16983 T3196 C178 P14070 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1357910861205/jetty4
[junit4:junit4] 2> 16983 T3196 C178 P14070 oass.SolrIndexSearcher.<init> Opening Searcher@45a8de31 main
[junit4:junit4] 2> 16985 T3195 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@45a8de31 mai
[...truncated too long message...]
nfiguration))
[junit4:junit4] 2> 158367 T3191 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 158367 T3103 oaz.ZooKeeper.close Session: 0x13c29cb659c000c closed
[junit4:junit4] 2> 158369 T3103 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/_d/e,null}
[junit4:junit4] 2> 158564 T3103 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=988BD8961AC3177C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_SA -Dtests.timezone=US/Pacific -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 159s 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([988BD8961AC3177C:196D568E6D9C7740]: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> 158597 T3103 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=ar_SA, timezone=US/Pacific
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=179820592,total=372244480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestPropInject, TestCSVLoader, TestJmxIntegration, ClusterStateTest, TestHashPartitioner, RequiredFieldsTest, TestRemoteStreaming, TestDocSet, DisMaxRequestHandlerTest, XsltUpdateRequestHandlerTest, SuggesterTest, TestRTGBase, LeaderElectionTest, TestStressReorder, TestCodecSupport, TestSurroundQueryParser, ZkNodePropsTest, ConvertedLegacyTest, DirectUpdateHandlerTest, TestReversedWildcardFilterFactory, OpenExchangeRatesOrgProviderTest, SolrInfoMBeanTest, ShardRoutingCustomTest, TestFunctionQuery, StatsComponentTest, FieldMutatingUpdateProcessorTest, TestStressRecovery, TestQuerySenderListener, TestPhraseSuggestions, ZkSolrClientTest, SignatureUpdateProcessorFactoryTest, LukeRequestHandlerTest, ShowFileRequestHandlerTest, FileUtilsTest, TestDistributedSearch, ShardRoutingTest, QueryParsingTest, SolrCoreTest, LegacyHTMLStripCharFilterTest, DOMUtilTest, TestSolr4Spatial, UUIDFieldTest, TestSolrDeletionPolicy2, TestDistributedGrouping, TestSolrJ, BasicFunctionalityTest, StandardRequestHandlerTest, IndexReaderFactoryTest, TestZkChroot, QueryEqualityTest, TestSolrXMLSerializer, TestStressLucene, ReturnFieldsTest, TestReplicationHandler, TestLRUCache, BadIndexSchemaTest, TestUpdate, TestRecovery, SuggesterTSTTest, OverseerTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, TestRealTimeGet, TestExtendedDismaxParser, SoftAutoCommitTest, AutoCommitTest, BasicZkTest, WordBreakSolrSpellCheckerTest, TestJoin, TestOmitPositions, TestArbitraryIndexDir, LoggingHandlerTest, UpdateParamsTest, NotRequiredUniqueKeyTest, TestFoldingMultitermQuery, SolrCoreCheckLockOnStartupTest, TestLuceneMatchVersion, UpdateRequestProcessorFactoryTest, NoCacheHeaderTest, AlternateDirectoryTest, HighlighterConfigTest, TestPropInjectDefaults, SolrIndexConfigTest, TestSolrCoreProperties, EchoParamsTest, TestPluginEnable, TestDFRSimilarityFactory, TestDefaultSimilarityFactory, TestFastLRUCache, URLClassifyProcessorTest, TestSystemIdResolver, TestUtils, PreAnalyzedFieldTest, PathHierarchyTokenizerFactoryTest, TestCharFilters, TestCollationKeyRangeQueries, ClusterStateUpdateTest, CollectionsAPIDistributedZkTest, OverseerCollectionProcessorTest, SyncSliceTest]
[junit4:junit4] Completed on J1 in 158.62s, 1 test, 1 failure <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:353: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:178: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:428: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1176: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:841: There were test failures: 247 suites, 1032 tests, 1 failure, 23 ignored (5 assumptions)
Total time: 38 minutes 21 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure