You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/03/15 23:43:49 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.6.0) - Build # 314 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/314/
Java: 64bit/jdk1.6.0 -XX:+UseConcMarkSweepGC
3 tests failed.
REGRESSION: org.apache.solr.core.TestSolrDiscoveryProperties.testPropertiesFile
Error Message:
Test abandoned because suite timeout was reached.
Stack Trace:
java.lang.Exception: Test abandoned because suite timeout was reached.
at __randomizedtesting.SeedInfo.seed([B2B53A5D6707D199]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.core.TestSolrDiscoveryProperties
Error Message:
Suite timeout exceeded (>= 7200000 msec).
Stack Trace:
java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
at __randomizedtesting.SeedInfo.seed([B2B53A5D6707D199]:0)
FAILED: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([B2B53A5D6707D199:3353B4451058B1A5]:0)
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertTrue(Assert.java:54)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:196)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:680)
Build Log:
[...truncated 8605 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T2663 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 20 T2663 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1363378910860
[junit4:junit4] 2> 21 T2663 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 27 T2664 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 29 T2664 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 29 T2664 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 30 T2664 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 31 T2664 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 31 T2663 oasc.ZkTestServer.run start zk server on port:52246
[junit4:junit4] 2> 32 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@c57101a
[junit4:junit4] 2> 33 T2664 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1363378910860/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 38 T2669 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 39 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 40 T2669 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 41 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52247
[junit4:junit4] 2> 42 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52247
[junit4:junit4] 2> 42 T2667 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 46 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990000 with negotiated timeout 10000 for client /127.0.0.1:52247
[junit4:junit4] 2> 48 T2669 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990000, negotiated timeout = 10000
[junit4:junit4] 2> 49 T2670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c57101a name:ZooKeeperConnection Watcher:127.0.0.1:52246 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 49 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 50 T2663 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 56 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb736990000
[junit4:junit4] 2> 60 T2670 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 60 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52247 which had sessionid 0x13d6fb736990000
[junit4:junit4] 2> 60 T2663 oaz.ZooKeeper.close Session: 0x13d6fb736990000 closed
[junit4:junit4] 2> 63 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@e0fadd2
[junit4:junit4] 2> 65 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 65 T2671 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 66 T2671 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 67 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52248
[junit4:junit4] 2> 68 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52248
[junit4:junit4] 2> 69 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990001 with negotiated timeout 10000 for client /127.0.0.1:52248
[junit4:junit4] 2> 69 T2671 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990001, negotiated timeout = 10000
[junit4:junit4] 2> 70 T2672 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e0fadd2 name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 70 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 71 T2663 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 77 T2663 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 82 T2663 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 87 T2663 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 92 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 93 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 104 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 105 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 112 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 113 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 118 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 119 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 127 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 128 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 133 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 134 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 139 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 140 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 145 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 146 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 151 T2663 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 152 T2663 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 157 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb736990001
[junit4:junit4] 2> 158 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52248 which had sessionid 0x13d6fb736990001
[junit4:junit4] 2> 158 T2672 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 160 T2663 oaz.ZooKeeper.close Session: 0x13d6fb736990001 closed
[junit4:junit4] 2> 441 T2663 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 461 T2663 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52249
[junit4:junit4] 2> 462 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 463 T2663 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 463 T2663 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000
[junit4:junit4] 2> 464 T2663 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/solr.xml
[junit4:junit4] 2> 464 T2663 oasc.CoreContainer.<init> New CoreContainer 145255522
[junit4:junit4] 2> 465 T2663 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/'
[junit4:junit4] 2> 466 T2663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/'
[junit4:junit4] 2> 565 T2663 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 566 T2663 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 566 T2663 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 567 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 568 T2663 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 568 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 569 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 569 T2663 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 570 T2663 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 570 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 596 T2663 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 615 T2663 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52246/solr
[junit4:junit4] 2> 617 T2663 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 617 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@402e74d7
[junit4:junit4] 2> 620 T2682 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 621 T2682 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 621 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52250
[junit4:junit4] 2> 621 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 622 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52250
[junit4:junit4] 2> 625 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990002 with negotiated timeout 20000 for client /127.0.0.1:52250
[junit4:junit4] 2> 625 T2682 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990002, negotiated timeout = 20000
[junit4:junit4] 2> 625 T2683 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@402e74d7 name:ZooKeeperConnection Watcher:127.0.0.1:52246 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 626 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 629 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb736990002
[junit4:junit4] 2> 630 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52250 which had sessionid 0x13d6fb736990002
[junit4:junit4] 2> 630 T2683 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 631 T2663 oaz.ZooKeeper.close Session: 0x13d6fb736990002 closed
[junit4:junit4] 2> 632 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 641 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7b0c24e1
[junit4:junit4] 2> 643 T2684 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 644 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 645 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52251
[junit4:junit4] 2> 645 T2684 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 646 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52251
[junit4:junit4] 2> 648 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990003 with negotiated timeout 20000 for client /127.0.0.1:52251
[junit4:junit4] 2> 648 T2684 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990003, negotiated timeout = 20000
[junit4:junit4] 2> 648 T2685 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b0c24e1 name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 649 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 652 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 655 T2663 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 666 T2663 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52249_
[junit4:junit4] 2> 668 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52249_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52249_
[junit4:junit4] 2> 669 T2663 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52249_
[junit4:junit4] 2> 675 T2663 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 685 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 686 T2663 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 690 T2663 oasc.Overseer.start Overseer (id=89350400302972931-127.0.0.1:52249_-n_0000000000) starting
[junit4:junit4] 2> 691 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 693 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 694 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 696 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 697 T2687 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 702 T2663 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 729 T2663 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 735 T2663 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 740 T2686 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 748 T2688 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/collection1
[junit4:junit4] 2> 748 T2688 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 749 T2688 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 750 T2688 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 752 T2688 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/collection1/'
[junit4:junit4] 2> 754 T2688 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 754 T2688 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/collection1/lib/README' to classloader
[junit4:junit4] 2> 866 T2688 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 973 T2688 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 975 T2688 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 983 T2688 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 2014 T2688 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 2027 T2688 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2031 T2688 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2058 T2688 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2065 T2688 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2071 T2688 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2073 T2688 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2074 T2688 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 2074 T2688 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 2076 T2688 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 2077 T2688 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 2077 T2688 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2077 T2688 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1363378911000/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/control/data/
[junit4:junit4] 2> 2078 T2688 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6d581e80
[junit4:junit4] 2> 2079 T2688 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2079 T2688 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/control/data forceNew: false
[junit4:junit4] 2> 2080 T2688 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363378910860/control/data/index/
[junit4:junit4] 2> 2080 T2688 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363378910860/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2080 T2688 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/control/data/index forceNew: false
[junit4:junit4] 2> 2084 T2688 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1116841 lockFactory=org.apache.lucene.store.NativeFSLockFactory@297bd5d1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 2084 T2688 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 2087 T2688 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2088 T2688 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2088 T2688 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2089 T2688 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2091 T2688 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2091 T2688 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2091 T2688 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2092 T2688 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2093 T2688 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2097 T2688 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2102 T2688 oass.SolrIndexSearcher.<init> Opening Searcher@9665619 main
[junit4:junit4] 2> 2103 T2688 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/control/data/tlog
[junit4:junit4] 2> 2104 T2688 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2104 T2688 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2108 T2689 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9665619 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2109 T2688 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2110 T2688 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2111 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 2257 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2258 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:52249_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52249"}
[junit4:junit4] 2> 2258 T2686 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2258 T2686 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2259 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 2277 T2685 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> 3116 T2688 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 3117 T2688 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52249 collection:control_collection shard:shard1
[junit4:junit4] 2> 3118 T2688 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 3131 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:delete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 3132 T2688 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 3133 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3136 T2688 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 3136 T2688 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 3136 T2688 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52249/collection1/
[junit4:junit4] 2> 3136 T2688 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 3137 T2688 oasc.SyncStrategy.syncToMe http://127.0.0.1:52249/collection1/ has no replicas
[junit4:junit4] 2> 3137 T2688 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52249/collection1/
[junit4:junit4] 2> 3137 T2688 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 3145 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3786 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3802 T2685 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> 3814 T2688 oasc.ZkController.register We are http://127.0.0.1:52249/collection1/ and leader is http://127.0.0.1:52249/collection1/
[junit4:junit4] 2> 3815 T2688 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52249
[junit4:junit4] 2> 3815 T2688 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3815 T2688 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3816 T2688 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3818 T2688 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3820 T2663 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3821 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3821 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3832 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3833 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3ced78ff
[junit4:junit4] 2> 3834 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3835 T2691 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3836 T2691 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 3836 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52252
[junit4:junit4] 2> 3837 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52252
[junit4:junit4] 2> 3839 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990004 with negotiated timeout 10000 for client /127.0.0.1:52252
[junit4:junit4] 2> 3839 T2691 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990004, negotiated timeout = 10000
[junit4:junit4] 2> 3840 T2692 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ced78ff name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3840 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3844 T2663 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3849 T2663 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4067 T2663 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4073 T2663 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52253
[junit4:junit4] 2> 4075 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4076 T2663 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4076 T2663 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688
[junit4:junit4] 2> 4077 T2663 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/solr.xml
[junit4:junit4] 2> 4077 T2663 oasc.CoreContainer.<init> New CoreContainer 940539153
[junit4:junit4] 2> 4079 T2663 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/'
[junit4:junit4] 2> 4080 T2663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/'
[junit4:junit4] 2> 4125 T2663 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 4126 T2663 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4126 T2663 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4127 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4128 T2663 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4128 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4129 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4129 T2663 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4130 T2663 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4131 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4149 T2663 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4183 T2663 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52246/solr
[junit4:junit4] 2> 4184 T2663 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4185 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1c63aa60
[junit4:junit4] 2> 4186 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4188 T2702 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4189 T2702 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 4190 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52254
[junit4:junit4] 2> 4190 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52254
[junit4:junit4] 2> 4192 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990005 with negotiated timeout 20000 for client /127.0.0.1:52254
[junit4:junit4] 2> 4192 T2702 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990005, negotiated timeout = 20000
[junit4:junit4] 2> 4193 T2703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c63aa60 name:ZooKeeperConnection Watcher:127.0.0.1:52246 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4193 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4197 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb736990005
[junit4:junit4] 2> 4198 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52254 which had sessionid 0x13d6fb736990005
[junit4:junit4] 2> 4198 T2703 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4198 T2663 oaz.ZooKeeper.close Session: 0x13d6fb736990005 closed
[junit4:junit4] 2> 4201 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4210 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3437caef
[junit4:junit4] 2> 4212 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4212 T2704 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4213 T2704 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 4214 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52255
[junit4:junit4] 2> 4214 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52255
[junit4:junit4] 2> 4216 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990006 with negotiated timeout 20000 for client /127.0.0.1:52255
[junit4:junit4] 2> 4216 T2704 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990006, negotiated timeout = 20000
[junit4:junit4] 2> 4217 T2705 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3437caef name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4217 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4219 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4220 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4224 T2663 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5230 T2663 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52253_
[junit4:junit4] 2> 5232 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52253_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52253_
[junit4:junit4] 2> 5233 T2663 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52253_
[junit4:junit4] 2> 5240 T2685 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 5243 T2692 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5243 T2705 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5247 T2685 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5254 T2706 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/collection1
[junit4:junit4] 2> 5254 T2706 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5256 T2706 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5256 T2706 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5258 T2706 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/collection1/'
[junit4:junit4] 2> 5259 T2706 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5259 T2706 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/collection1/lib/README' to classloader
[junit4:junit4] 2> 5313 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5315 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:52249_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52249"}
[junit4:junit4] 2> 5323 T2685 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> 5324 T2692 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> 5324 T2705 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> 5332 T2706 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 5413 T2706 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5415 T2706 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5427 T2706 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 6405 T2706 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 6417 T2706 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 6439 T2706 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 6470 T2706 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6476 T2706 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6483 T2706 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6485 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6486 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 6486 T2706 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6489 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6489 T2706 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 6490 T2706 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6490 T2706 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1363378914688/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty1/
[junit4:junit4] 2> 6490 T2706 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6d581e80
[junit4:junit4] 2> 6492 T2706 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6492 T2706 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty1 forceNew: false
[junit4:junit4] 2> 6493 T2706 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty1/index/
[junit4:junit4] 2> 6493 T2706 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 6494 T2706 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty1/index forceNew: false
[junit4:junit4] 2> 6496 T2706 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 6497 T2706 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 6501 T2706 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 6501 T2706 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 6502 T2706 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 6503 T2706 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 6504 T2706 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 6504 T2706 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 6505 T2706 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 6507 T2706 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 6508 T2706 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 6512 T2706 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 6550 T2706 oass.SolrIndexSearcher.<init> Opening Searcher@6e4114b2 main
[junit4:junit4] 2> 6551 T2706 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty1/tlog
[junit4:junit4] 2> 6552 T2706 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 6552 T2706 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 6557 T2707 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e4114b2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 6562 T2706 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 6562 T2706 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6838 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6840 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52253_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52253"}
[junit4:junit4] 2> 6841 T2686 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6841 T2686 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6852 T2685 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> 6855 T2705 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> 6856 T2692 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> 7566 T2706 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7566 T2706 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52253 collection:collection1 shard:shard1
[junit4:junit4] 2> 7567 T2706 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7580 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990006 type:delete cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7582 T2706 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7582 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7586 T2706 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7587 T2706 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7587 T2706 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 7587 T2706 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7588 T2706 oasc.SyncStrategy.syncToMe http://127.0.0.1:52253/collection1/ has no replicas
[junit4:junit4] 2> 7588 T2706 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 7588 T2706 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7597 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8371 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8388 T2692 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> 8389 T2705 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> 8389 T2685 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> 8393 T2706 oasc.ZkController.register We are http://127.0.0.1:52253/collection1/ and leader is http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 8393 T2706 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52253
[junit4:junit4] 2> 8394 T2706 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8394 T2706 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8394 T2706 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8400 T2706 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8402 T2663 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8403 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8403 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8617 T2663 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8634 T2663 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52256
[junit4:junit4] 2> 8636 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8637 T2663 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8638 T2663 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252
[junit4:junit4] 2> 8638 T2663 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/solr.xml
[junit4:junit4] 2> 8639 T2663 oasc.CoreContainer.<init> New CoreContainer 2032275313
[junit4:junit4] 2> 8640 T2663 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/'
[junit4:junit4] 2> 8641 T2663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/'
[junit4:junit4] 2> 8679 T2663 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8681 T2663 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8681 T2663 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8682 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8682 T2663 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8683 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8683 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8683 T2663 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8684 T2663 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8685 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8700 T2663 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8722 T2663 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52246/solr
[junit4:junit4] 2> 8723 T2663 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8724 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@48f52208
[junit4:junit4] 2> 8726 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8726 T2718 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8727 T2718 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 8728 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52257
[junit4:junit4] 2> 8728 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52257
[junit4:junit4] 2> 8730 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990007 with negotiated timeout 20000 for client /127.0.0.1:52257
[junit4:junit4] 2> 8730 T2718 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990007, negotiated timeout = 20000
[junit4:junit4] 2> 8730 T2719 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48f52208 name:ZooKeeperConnection Watcher:127.0.0.1:52246 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8731 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8734 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb736990007
[junit4:junit4] 2> 8735 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52257 which had sessionid 0x13d6fb736990007
[junit4:junit4] 2> 8735 T2719 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8735 T2663 oaz.ZooKeeper.close Session: 0x13d6fb736990007 closed
[junit4:junit4] 2> 8738 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8754 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5f236210
[junit4:junit4] 2> 8756 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8756 T2720 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8758 T2720 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 8758 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52258
[junit4:junit4] 2> 8759 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52258
[junit4:junit4] 2> 8760 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990008 with negotiated timeout 20000 for client /127.0.0.1:52258
[junit4:junit4] 2> 8761 T2720 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990008, negotiated timeout = 20000
[junit4:junit4] 2> 8761 T2721 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f236210 name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8761 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8765 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8767 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8771 T2663 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9778 T2663 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52256_
[junit4:junit4] 2> 9779 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb736990008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52256_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52256_
[junit4:junit4] 2> 9780 T2663 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52256_
[junit4:junit4] 2> 9785 T2692 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> 9788 T2685 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> 9789 T2721 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9790 T2705 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9790 T2705 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> 9794 T2685 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9794 T2692 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9806 T2722 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/collection1
[junit4:junit4] 2> 9806 T2722 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9808 T2722 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9808 T2722 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9811 T2722 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/collection1/'
[junit4:junit4] 2> 9812 T2722 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9813 T2722 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/collection1/lib/README' to classloader
[junit4:junit4] 2> 9868 T2722 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 9905 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9907 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52253_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52253"}
[junit4:junit4] 2> 9914 T2692 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> 9914 T2721 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> 9915 T2705 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> 9916 T2685 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> 9949 T2722 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9951 T2722 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9958 T2722 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10708 T2722 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10720 T2722 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10726 T2722 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10754 T2722 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10760 T2722 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10766 T2722 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10769 T2722 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10769 T2722 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10769 T2722 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10772 T2722 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10772 T2722 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10773 T2722 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10773 T2722 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1363378919252/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2/
[junit4:junit4] 2> 10773 T2722 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6d581e80
[junit4:junit4] 2> 10774 T2722 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10775 T2722 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2 forceNew: false
[junit4:junit4] 2> 10775 T2722 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2/index/
[junit4:junit4] 2> 10776 T2722 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10776 T2722 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2/index forceNew: false
[junit4:junit4] 2> 10779 T2722 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10779 T2722 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10782 T2722 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10783 T2722 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10784 T2722 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10785 T2722 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10786 T2722 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10786 T2722 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10786 T2722 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10788 T2722 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10788 T2722 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10792 T2722 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10798 T2722 oass.SolrIndexSearcher.<init> Opening Searcher@77cb609b main
[junit4:junit4] 2> 10798 T2722 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2/tlog
[junit4:junit4] 2> 10799 T2722 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10800 T2722 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10813 T2723 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77cb609b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10817 T2722 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10817 T2722 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11431 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11432 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52256_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52256"}
[junit4:junit4] 2> 11432 T2686 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11433 T2686 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11441 T2692 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> 11441 T2705 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> 11441 T2685 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> 11441 T2721 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> 11820 T2722 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11821 T2722 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52256 collection:collection1 shard:shard1
[junit4:junit4] 2> 11828 T2722 oasc.ZkController.register We are http://127.0.0.1:52256/collection1/ and leader is http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 11828 T2722 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52256
[junit4:junit4] 2> 11828 T2722 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11829 T2722 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C180 name=collection1 org.apache.solr.core.SolrCore@5c98c2f2 url=http://127.0.0.1:52256/collection1 node=127.0.0.1:52256_ C180_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52256_, base_url=http://127.0.0.1:52256}
[junit4:junit4] 2> 11830 T2724 C180 P52256 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11838 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11838 T2722 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11838 T2724 C180 P52256 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11839 T2724 C180 P52256 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11841 T2724 C180 P52256 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11841 T2663 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11842 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11843 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12072 T2663 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 12194 T2663 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52260
[junit4:junit4] 2> 12204 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 12204 T2663 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 12205 T2663 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695
[junit4:junit4] 2> 12205 T2663 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/solr.xml
[junit4:junit4] 2> 12206 T2663 oasc.CoreContainer.<init> New CoreContainer 307560272
[junit4:junit4] 2> 12207 T2663 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/'
[junit4:junit4] 2> 12207 T2663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/'
[junit4:junit4] 2> 12246 T2663 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 12247 T2663 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 12248 T2663 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 12248 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 12249 T2663 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 12249 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 12250 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 12250 T2663 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 12251 T2663 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 12252 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 12279 T2663 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 12299 T2663 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52246/solr
[junit4:junit4] 2> 12300 T2663 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 12300 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@35a03892
[junit4:junit4] 2> 12302 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12303 T2735 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 12304 T2735 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 12305 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52261
[junit4:junit4] 2> 12306 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52261
[junit4:junit4] 2> 12308 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb736990009 with negotiated timeout 20000 for client /127.0.0.1:52261
[junit4:junit4] 2> 12308 T2735 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb736990009, negotiated timeout = 20000
[junit4:junit4] 2> 12309 T2736 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@35a03892 name:ZooKeeperConnection Watcher:127.0.0.1:52246 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12309 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12313 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb736990009
[junit4:junit4] 2> 12314 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52261 which had sessionid 0x13d6fb736990009
[junit4:junit4] 2> 12315 T2736 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 12315 T2663 oaz.ZooKeeper.close Session: 0x13d6fb736990009 closed
[junit4:junit4] 2> 12317 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 12330 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@207aa23
[junit4:junit4] 2> 12333 T2737 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 12332 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12334 T2737 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 12334 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52262
[junit4:junit4] 2> 12335 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52262
[junit4:junit4] 2> 12337 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb73699000a with negotiated timeout 20000 for client /127.0.0.1:52262
[junit4:junit4] 2> 12337 T2737 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb73699000a, negotiated timeout = 20000
[junit4:junit4] 2> 12338 T2738 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@207aa23 name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12338 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12342 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb73699000a type:create cxid:0x1 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12344 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb73699000a type:create cxid:0x2 zxid:0x82 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12348 T2663 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12954 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12956 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52256_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52256"}
[junit4:junit4] 2> 12964 T2692 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> 12965 T2738 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> 12965 T2721 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> 12965 T2705 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> 12965 T2685 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> 13357 T2663 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52260_
[junit4:junit4] 2> 13359 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb73699000a type:delete cxid:0xd zxid:0x87 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52260_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52260_
[junit4:junit4] 2> 13360 T2663 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52260_
[junit4:junit4] 2> 13366 T2685 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> 13366 T2692 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> 13366 T2721 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> 13369 T2738 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13369 T2738 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> 13369 T2705 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13371 T2705 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> 13377 T2685 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13377 T2721 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13378 T2692 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13390 T2739 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/collection1
[junit4:junit4] 2> 13390 T2739 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 13396 T2739 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 13397 T2739 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 13400 T2739 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/collection1/'
[junit4:junit4] 2> 13404 T2739 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 13405 T2739 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/collection1/lib/README' to classloader
[junit4:junit4] 2> 13492 T2739 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 13582 T2739 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13584 T2739 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13593 T2739 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13862 T2701 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=3&state=recovering&nodeName=127.0.0.1:52256_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 14502 T2739 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 14511 T2739 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 14516 T2739 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 14545 T2739 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14553 T2739 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14562 T2739 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14566 T2739 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 14566 T2739 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 14567 T2739 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14570 T2739 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 14571 T2739 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 14571 T2739 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14572 T2739 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1363378922695/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3/
[junit4:junit4] 2> 14572 T2739 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6d581e80
[junit4:junit4] 2> 14573 T2739 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14574 T2739 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3 forceNew: false
[junit4:junit4] 2> 14574 T2739 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3/index/
[junit4:junit4] 2> 14574 T2739 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 14575 T2739 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3/index forceNew: false
[junit4:junit4] 2> 14579 T2739 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 14579 T2739 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 14583 T2739 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 14584 T2739 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 14584 T2739 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 14585 T2739 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 14586 T2739 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 14586 T2739 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 14587 T2739 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 14588 T2739 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 14588 T2739 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 14593 T2739 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 14598 T2739 oass.SolrIndexSearcher.<init> Opening Searcher@c49c04 main
[junit4:junit4] 2> 14598 T2739 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3/tlog
[junit4:junit4] 2> 14599 T2739 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 14600 T2739 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 14605 T2740 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c49c04 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 14608 T2739 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 14608 T2739 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> C180_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52256_, base_url=http://127.0.0.1:52256}
[junit4:junit4] 2> 15866 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52253/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15867 T2724 C180 P52256 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52256 START replicas=[http://127.0.0.1:52253/collection1/] nUpdates=100
[junit4:junit4] 2> 15867 T2724 C180 P52256 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15868 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15868 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15869 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15869 T2724 C180 P52256 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15870 T2724 C180 P52256 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52253/collection1/. core=collection1
[junit4:junit4] 2> 15870 T2724 C180 P52256 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C181 name=collection1 org.apache.solr.core.SolrCore@bbccafa url=http://127.0.0.1:52253/collection1 node=127.0.0.1:52253_ C181_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52253_, base_url=http://127.0.0.1:52253, leader=true}
[junit4:junit4] 2> 15876 T2700 C181 P52253 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 15886 T2697 C181 P52253 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 15889 T2697 C181 P52253 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15889 T2697 C181 P52253 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15890 T2697 C181 P52253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15891 T2697 C181 P52253 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15892 T2697 C181 P52253 oass.SolrIndexSearcher.<init> Opening Searcher@1b557067 realtime
[junit4:junit4] 2> 15892 T2697 C181 P52253 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15893 T2697 C181 P52253 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 15894 T2724 C180 P52256 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15894 T2724 C180 P52256 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15897 T2699 C181 P52253 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15898 T2699 C181 P52253 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 15899 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 15899 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15900 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15904 T2701 C181 P52253 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 15905 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15907 T2724 C180 P52256 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty2/index.20130315152206745 forceNew: false
[junit4:junit4] 2> 15907 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@586a75b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@afcdfde) fullCopy=false
[junit4:junit4] 2> 15919 T2700 C181 P52253 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 15920 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15922 T2724 C180 P52256 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15922 T2724 C180 P52256 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15924 T2724 C180 P52256 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15925 T2724 C180 P52256 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15925 T2724 C180 P52256 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15926 T2724 C180 P52256 oass.SolrIndexSearcher.<init> Opening Searcher@44d2c37d main
[junit4:junit4] 2> 15927 T2723 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44d2c37d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 15928 T2724 C180 P52256 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@586a75b4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@afcdfde)
[junit4:junit4] 2> 15928 T2724 C180 P52256 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15928 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15928 T2724 C180 P52256 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15929 T2724 C180 P52256 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15931 T2724 C180 P52256 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15986 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15988 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52260_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52260"}
[junit4:junit4] 2> 15989 T2686 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 15990 T2686 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 16005 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52256_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52256"}
[junit4:junit4] 2> 16014 T2692 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> 16015 T2738 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> 16015 T2705 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> 16015 T2685 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> 16015 T2721 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> 16612 T2739 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 16612 T2739 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52260 collection:collection1 shard:shard1
[junit4:junit4] 2> 16620 T2739 oasc.ZkController.register We are http://127.0.0.1:52260/collection1/ and leader is http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 16620 T2739 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52260
[junit4:junit4] 2> 16621 T2739 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 16621 T2739 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C182 name=collection1 org.apache.solr.core.SolrCore@5e6d6e9e url=http://127.0.0.1:52260/collection1 node=127.0.0.1:52260_ C182_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52260_, base_url=http://127.0.0.1:52260}
[junit4:junit4] 2> 16622 T2743 C182 P52260 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 16623 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 16623 T2739 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16623 T2743 C182 P52260 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 16624 T2743 C182 P52260 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16625 T2663 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 16626 T2743 C182 P52260 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16626 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 16627 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16871 T2663 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 16875 T2663 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52267
[junit4:junit4] 2> 16877 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 16878 T2663 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 16878 T2663 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479
[junit4:junit4] 2> 16879 T2663 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/solr.xml
[junit4:junit4] 2> 16879 T2663 oasc.CoreContainer.<init> New CoreContainer 477169424
[junit4:junit4] 2> 16880 T2663 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/'
[junit4:junit4] 2> 16880 T2663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/'
[junit4:junit4] 2> 16914 T2663 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 16915 T2663 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 16916 T2663 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 16916 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 16917 T2663 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 16917 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 16918 T2663 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 16918 T2663 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 16919 T2663 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 16920 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 16948 T2663 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 16969 T2663 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:52246/solr
[junit4:junit4] 2> 16970 T2663 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 16971 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2e7b51dc
[junit4:junit4] 2> 16972 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16973 T2754 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 16974 T2754 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 16975 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52268
[junit4:junit4] 2> 16976 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52268
[junit4:junit4] 2> 16977 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb73699000b with negotiated timeout 20000 for client /127.0.0.1:52268
[junit4:junit4] 2> 16978 T2754 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb73699000b, negotiated timeout = 20000
[junit4:junit4] 2> 16978 T2755 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e7b51dc name:ZooKeeperConnection Watcher:127.0.0.1:52246 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16979 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16981 T2668 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d6fb73699000b
[junit4:junit4] 2> 16982 T2665 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:52268 which had sessionid 0x13d6fb73699000b
[junit4:junit4] 2> 16982 T2663 oaz.ZooKeeper.close Session: 0x13d6fb73699000b closed
[junit4:junit4] 2> 16983 T2755 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 16983 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 17001 T2663 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:52246/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4cd671a1
[junit4:junit4] 2> 17003 T2663 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 17004 T2756 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server 127.0.0.1/127.0.0.1:52246. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 17006 T2756 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to 127.0.0.1/127.0.0.1:52246, initiating session
[junit4:junit4] 2> 17006 T2665 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:52269
[junit4:junit4] 2> 17007 T2665 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:52269
[junit4:junit4] 2> 17008 T2667 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d6fb73699000c with negotiated timeout 20000 for client /127.0.0.1:52269
[junit4:junit4] 2> 17008 T2756 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server 127.0.0.1/127.0.0.1:52246, sessionid = 0x13d6fb73699000c, negotiated timeout = 20000
[junit4:junit4] 2> 17009 T2757 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cd671a1 name:ZooKeeperConnection Watcher:127.0.0.1:52246/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 17010 T2663 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 17012 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb73699000c type:create cxid:0x1 zxid:0x98 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 17014 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb73699000c type:create cxid:0x2 zxid:0x99 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 17019 T2663 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 17546 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17550 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52260_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52260"}
[junit4:junit4] 2> 17569 T2705 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> 17569 T2692 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> 17570 T2738 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> 17569 T2757 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> 17571 T2685 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> 17570 T2721 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> 17644 T2697 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=4&state=recovering&nodeName=127.0.0.1:52260_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 18029 T2663 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52267_
[junit4:junit4] 2> 18033 T2668 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d6fb73699000c type:delete cxid:0xd zxid:0x9e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52267_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52267_
[junit4:junit4] 2> 18037 T2663 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52267_
[junit4:junit4] 2> 18049 T2692 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> 18054 T2721 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> 18055 T2757 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> 18056 T2685 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> 18063 T2705 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 18063 T2705 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> 18063 T2738 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 18063 T2738 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> 18068 T2692 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 18070 T2757 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 18070 T2685 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 18070 T2721 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 18078 T2758 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/collection1
[junit4:junit4] 2> 18079 T2758 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 18080 T2758 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 18080 T2758 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 18082 T2758 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/collection1/'
[junit4:junit4] 2> 18084 T2758 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 18084 T2758 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/collection1/lib/README' to classloader
[junit4:junit4] 2> 18147 T2758 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4] 2> 18214 T2758 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 18216 T2758 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 18222 T2758 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 19025 T2758 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 19038 T2758 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 19043 T2758 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 19068 T2758 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 19075 T2758 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 19081 T2758 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 19083 T2758 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 19084 T2758 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 19084 T2758 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 19086 T2758 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 19087 T2758 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 19087 T2758 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 19088 T2758 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1363378927479/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4/
[junit4:junit4] 2> 19088 T2758 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6d581e80
[junit4:junit4] 2> 19089 T2758 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 19089 T2758 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4 forceNew: false
[junit4:junit4] 2> 19090 T2758 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4/index/
[junit4:junit4] 2> 19090 T2758 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 19091 T2758 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4/index forceNew: false
[junit4:junit4] 2> 19094 T2758 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 19094 T2758 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 19098 T2758 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 19098 T2758 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 19099 T2758 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 19101 T2758 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 19103 T2758 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 19103 T2758 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 19104 T2758 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 19105 T2758 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 19106 T2758 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 19113 T2758 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 19146 T2758 oass.SolrIndexSearcher.<init> Opening Searcher@c9f6d46 main
[junit4:junit4] 2> 19147 T2758 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4/tlog
[junit4:junit4] 2> 19149 T2758 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 19149 T2758 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 19156 T2759 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c9f6d46 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 19159 T2758 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 19159 T2758 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> C182_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52260_, base_url=http://127.0.0.1:52260}
[junit4:junit4] 2> 19649 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52253/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 19649 T2743 C182 P52260 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52260 START replicas=[http://127.0.0.1:52253/collection1/] nUpdates=100
[junit4:junit4] 2> 19650 T2743 C182 P52260 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 19651 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 19652 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 19652 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 19653 T2743 C182 P52260 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 19653 T2743 C182 P52260 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52253/collection1/. core=collection1
[junit4:junit4] 2> 19654 T2743 C182 P52260 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19655 T2697 C181 P52253 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 19688 T2700 C181 P52253 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 19691 T2700 C181 P52253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 19692 T2700 C181 P52253 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 19692 T2700 C181 P52253 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19693 T2700 C181 P52253 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 19694 T2743 C182 P52260 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19695 T2743 C182 P52260 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 19699 T2698 C181 P52253 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 19700 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 19700 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 19701 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 19706 T2699 C181 P52253 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0
[junit4:junit4] 2> 19707 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 19710 T2743 C182 P52260 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty3/index.20130315152210547 forceNew: false
[junit4:junit4] 2> 19710 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@780c4520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@23c0c78f) fullCopy=false
[junit4:junit4] 2> 19713 T2697 C181 P52253 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 19719 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 19720 T2743 C182 P52260 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 19720 T2743 C182 P52260 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 19722 T2743 C182 P52260 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 19723 T2743 C182 P52260 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 19723 T2743 C182 P52260 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 19724 T2743 C182 P52260 oass.SolrIndexSearcher.<init> Opening Searcher@1a104790 main
[junit4:junit4] 2> 19725 T2740 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a104790 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 19734 T2743 C182 P52260 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@780c4520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@23c0c78f)
[junit4:junit4] 2> 19734 T2743 C182 P52260 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 19734 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 19734 T2743 C182 P52260 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 19734 T2743 C182 P52260 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19736 T2743 C182 P52260 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 20616 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20623 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52267_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52267"}
[junit4:junit4] 2> 20625 T2686 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 20625 T2686 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 20647 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52260_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52260"}
[junit4:junit4] 2> 20663 T2705 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> 20663 T2692 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> 20664 T2757 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> 20664 T2685 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> 20663 T2721 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> 20663 T2738 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> 21166 T2758 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 21167 T2758 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52267 collection:collection1 shard:shard1
[junit4:junit4] 2> 21174 T2758 oasc.ZkController.register We are http://127.0.0.1:52267/collection1/ and leader is http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 21175 T2758 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52267
[junit4:junit4] 2> 21175 T2758 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 21175 T2758 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C183 name=collection1 org.apache.solr.core.SolrCore@62bbffbc url=http://127.0.0.1:52267/collection1 node=127.0.0.1:52267_ C183_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52267_, base_url=http://127.0.0.1:52267}
[junit4:junit4] 2> 21177 T2762 C183 P52267 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 21181 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 21181 T2758 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21187 T2762 C183 P52267 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 21187 T2762 C183 P52267 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21189 T2663 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 21189 T2762 C183 P52267 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21190 T2663 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 21190 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21202 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21205 T2663 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 21205 T2663 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 21207 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22183 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22184 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52267_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52267"}
[junit4:junit4] 2> 22192 T2692 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> 22193 T2705 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> 22193 T2685 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> 22193 T2757 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> 22192 T2738 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> 22193 T2721 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> 22206 T2698 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {coreNodeName=5&state=recovering&nodeName=127.0.0.1:52267_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 22210 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23214 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C183_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52267_, base_url=http://127.0.0.1:52267}
[junit4:junit4] 2> 24208 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52253/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 24209 T2762 C183 P52267 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52267 START replicas=[http://127.0.0.1:52253/collection1/] nUpdates=100
[junit4:junit4] 2> 24211 T2762 C183 P52267 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 24212 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 24212 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 24212 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 24213 T2762 C183 P52267 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 24213 T2762 C183 P52267 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52253/collection1/. core=collection1
[junit4:junit4] 2> 24213 T2762 C183 P52267 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 24214 T2698 C181 P52253 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 24219 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 24234 T2700 C181 P52253 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 24235 T2700 C181 P52253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 24236 T2700 C181 P52253 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 24236 T2700 C181 P52253 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 24237 T2700 C181 P52253 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 24238 T2762 C183 P52267 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 24239 T2762 C183 P52267 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 24242 T2699 C181 P52253 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 24243 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 24244 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 24244 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 24247 T2697 C181 P52253 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 24248 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 24254 T2762 C183 P52267 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1363378910860/jetty4/index.20130315152215088 forceNew: false
[junit4:junit4] 2> 24254 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5380477a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ecb7b4) fullCopy=false
[junit4:junit4] 2> 24259 T2698 C181 P52253 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 24262 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 24264 T2762 C183 P52267 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 24265 T2762 C183 P52267 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 24267 T2762 C183 P52267 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 24268 T2762 C183 P52267 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 24269 T2762 C183 P52267 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 24270 T2762 C183 P52267 oass.SolrIndexSearcher.<init> Opening Searcher@110b432d main
[junit4:junit4] 2> 24272 T2759 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@110b432d main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 24273 T2762 C183 P52267 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@5380477a lockFactory=org.apache.lucene.store.NativeFSLockFactory@16ecb7b4)
[junit4:junit4] 2> 24273 T2762 C183 P52267 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 24273 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 24274 T2762 C183 P52267 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 24274 T2762 C183 P52267 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 24277 T2762 C183 P52267 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 25216 T2686 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 25218 T2686 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52267_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52267"}
[junit4:junit4] 2> 25223 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 25227 T2692 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> 25228 T2738 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> 25228 T2685 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> 25229 T2721 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> 25229 T2757 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> 25228 T2705 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> 26232 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 26233 T2663 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C184 name=collection1 org.apache.solr.core.SolrCore@199bbe5 url=http://127.0.0.1:52249/collection1 node=127.0.0.1:52249_ C184_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:52249_, base_url=http://127.0.0.1:52249, leader=true}
[junit4:junit4] 2> 26241 T2677 C184 P52249 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26245 T2677 C184 P52249 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1116841 lockFactory=org.apache.lucene.store.NativeFSLockFactory@297bd5d1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 26246 T2677 C184 P52249 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 26247 T2677 C184 P52249 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1116841 lockFactory=org.apache.lucene.store.NativeFSLockFactory@297bd5d1),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1116841 lockFactory=org.apache.lucene.store.NativeFSLockFactory@297bd5d1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 26248 T2677 C184 P52249 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 26249 T2677 C184 P52249 oass.SolrIndexSearcher.<init> Opening Searcher@673074aa main
[junit4:junit4] 2> 26250 T2677 C184 P52249 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26250 T2689 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@673074aa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 26251 T2677 C184 P52249 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 26260 T2697 C181 P52253 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26260 T2697 C181 P52253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 26261 T2697 C181 P52253 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 26262 T2697 C181 P52253 oass.SolrIndexSearcher.<init> Opening Searcher@39c57bf4 main
[junit4:junit4] 2> 26262 T2697 C181 P52253 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26264 T2707 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@39c57bf4 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 26265 T2697 C181 P52253 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:52256/collection1/, StdNode: http://127.0.0.1:52260/collection1/, StdNode: http://127.0.0.1:52267/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C183_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52267_, base_url=http://127.0.0.1:52267}
[junit4:junit4] 2> 26305 T2751 C183 P52267 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C180_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52256_, base_url=http://127.0.0.1:52256}
[junit4:junit4] 2> 26319 T2712 C180 P52256 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C182_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52260_, base_url=http://127.0.0.1:52260}
[junit4:junit4] 2> 26333 T2733 C182 P52260 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 26333 T2751 C183 P52267 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 26334 T2751 C183 P52267 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 26335 T2712 C180 P52256 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 26336 T2751 C183 P52267 oass.SolrIndexSearcher.<init> Opening Searcher@5a5be41 main
[junit4:junit4] 2> 26336 T2712 C180 P52256 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 26337 T2751 C183 P52267 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26337 T2712 C180 P52256 oass.SolrIndexSearcher.<init> Opening Searcher@a0d5a60 main
[junit4:junit4] 2> 26339 T2712 C180 P52256 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26340 T2759 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5a5be41 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 26340 T2733 C182 P52260 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 26341 T2733 C182 P52260 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 26340 T2751 C183 P52267 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 35
[junit4:junit4] 2> 26342 T2733 C182 P52260 oass.SolrIndexSearcher.<init> Opening Searcher@20428bd2 main
[junit4:junit4] 2> 26342 T2723 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a0d5a60 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 26343 T2733 C182 P52260 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 26345 T2712 C180 P52256 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4] 2> 26346 T2740 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@20428bd2 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 26347 T2733 C182 P52260 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 26348 T2697 C181 P52253 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 88
[junit4:junit4] 2> 26350 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 26356 T2701 C181 P52253 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 26363 T2714 C180 P52256 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 26368 T2734 C182 P52260 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 26374 T2752 C183 P52267 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 28384 T2677 C184 P52249 oass.SolrIndexSearcher.<init> Opening Searcher@3d1309b8 realtime
[junit4:junit4] 2> 28385 T2677 C184 P52249 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1429606434572599296)} 0 3
[junit4:junit4] 2> 28397 T2752 C183 P52267 /update {update.distrib=FROMLEADER&_version_=-1429606434583085056&update.from=http://127.0.0.1:52253/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429606434583085056)} 0 1
[junit4:junit4] 2> 28407 T2734 C182 P52260 /update {update.distrib=FROMLEADER&_version_=-1429606434583085056&update.from=http://127.0.0.1:52253/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429606434583085056)} 0 10
[junit4:junit4] 2> 28408 T2713 C180 P52256 /update {update.distrib=FROMLEADER&_version_=-1429606434583085056&update.from=http://127.0.0.1:52253/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1429606434583085056)} 0 12
[junit4:junit4] 2> 28409 T2701 C181 P52253 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1429606434583085056)} 0 18
[junit4:junit4] 2> 28420 T2678 C184 P52249 /update {wt=javabin&version=2} {add=[0 (1429606434610348032)]} 0 2
[junit4:junit4] 2> 28431 T2729 C182 P52260 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429606434616639488)]} 0 3
[junit4:junit4] 2> 28432 T2753 C183 P52267 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429606434616639488)]} 0 4
[junit4:junit4] 2> 28433 T2714 C180 P52256 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1429606434616639488)]} 0 3
[junit4:junit4] 2> 28434 T2700 C181 P52253 /update {wt=javabin&version=2} {add=[0 (1429606434616639488)]} 0 10
[junit4:junit4] 2> 28449 T2679 C184 P52249 /update {wt=javabin&version=2} {add=[1 (1429606434641805312)]} 0 1
[junit4:junit4] 2> 28461 T2730 C182 P52260 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429606434648096768)]} 0 2
[junit4:junit4] 2> 28463 T2715 C180 P52256 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429606434648096768)]} 0 2
[junit4:junit4] 2> 28464 T2748 C183 P52267 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1429606434648096768)]} 0 4
[junit4:junit4] 2> 28466 T2696 C181 P52253 /update {wt=javabin&version=2} {add=[1 (1429606434648096768)]} 0 12
[junit4:junit4] 2> 28474 T2680 C184 P52249 /update {wt=javabin&version=2} {add=[2 (1429606434666971136)]} 0 2
[junit4:junit4] 2> 28487 T2749 C183 P52267 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1429606434676408320)]} 0 2
[junit4:junit4] 2> 28487 T2731 C182 P52260 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1429606434676408320)]} 0 2
[junit4:junit4] 2> 28489 T2699 C181 P52253 /update {test.distrib.skip.servers=http://127.0.0.1:52256/collection1/&wt=javabin&version=2} {add=[2 (1429606434676408320)]} 0 9
[junit4:junit4] 2> 28497 T2681 C184 P52249 /update {wt=javabin&version=2} {add=[3 (1429606434691088384)]} 0 2
[junit4:junit4] 2> 28514 T2750 C183 P52267 /update {distrib.from=http://127.0.0.1:52253/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1429606434703671296)]} 0 2
[junit4:junit4] 2> 28516 T2697 C181 P52253 /update {test.distrib.skip.servers=http://127.0.0.1:52256/collection1/&test.distrib.skip.servers=http://127.0.0.1:52260/collection1/&wt=javabin&version=2} {add=[3 (1429606434703671296)]} 0 9
[junit4:junit4] 2> 28522 T2676 C184 P52249 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 28535 T2676 C184 P52249 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1116841 lockFactory=org.apache.lucene.store.NativeFSLockFactory@297bd5d1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1116841 lockFactory=org.apache.lucene.store.NativeFSLockFactory@297bd5d1),segFN=segments_3,generation=3,filenames=[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_3]
[junit4:junit4] 2> 28535 T2676 C184 P52249 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_3]
[junit4:junit4] 2> 28590 T2676 C184 P52249 oass.SolrIndexSearcher.<init> Opening Searcher@1583f012 main
[junit4:junit4] 2> 28593 T2689 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1583f012 main{StandardDirectoryReader(segments_3:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 28592 T2676 C184 P52249 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 28594 T2676 C184 P52249 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 72
[junit4:junit4] 2> 28598 T2698 C181 P52253 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 28618 T2698 C181 P52253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3312a3e2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@73514aec),segFN=segments_6,generation=6,filenames=[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, segments_6, _0.fdt]
[junit4:junit4] 2> 28619 T2698 C181 P52253 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, segments_6, _0.fdt]
[junit4:junit4] 2> 28623 T2698 C181 P52253 oass.SolrIndexSearcher.<init> Opening Searcher@3a1ffad2 main
[junit4:junit4] 2> 28624 T2698 C181 P52253 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 28625 T2707 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a1ffad2 main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 28626 T2698 C181 P52253 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:52256/collection1/, StdNode: http://127.0.0.1:52260/collection1/, StdNode: http://127.0.0.1:52267/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 28630 T2732 C182 P52260 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 28636 T2716 C180 P52256 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 28642 T2751 C183 P52267 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 28685 T2751 C183 P52267 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1edd7ad9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cb2824),segFN=segments_6,generation=6,filenames=[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, segments_6, _0.fdt]
[junit4:junit4] 2> 28687 T2751 C183 P52267 oasc.SolrDeletionPolicy.updateCommits newest commit = 6[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, segments_6, _0.fdt]
[junit4:junit4] 2> 28692 T2716 C180 P52256 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2951bb0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5c1be6a0),segFN=segments_4,generation=4,filenames=[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_4]
[junit4:junit4] 2> 28692 T2716 C180 P52256 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, _0_MockSep_0.pyl, _0.fdt, segments_4]
[junit4:junit4] 2> 28690 T2732 C182 P52260 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@431ee45 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41383426),segFN=segments_5,generation=5,filenames=[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, segments_5, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> 28695 T2732 C182 P52260 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[_0_MockSep_0.pos, _0_MockVariableIntBlock_0.doc, _0_MockVariableIntBlock_0.skp, _0_NestedPulsing_0.tip, _0_NestedPulsing_0.tim, _0_MockVariableIntBlock_0.pyl, _0_NestedPulsing_0.pos, _0_MockVariableIntBlock_0.tib, _0_MockSep_0.skp, _0.nvd, _0_MockVariableIntBlock_0.pos, _0_MockSep_0.doc, _0.si, _0_MockVariableIntBlock_0.tii, _0_NestedPulsing_0.doc, _0.fnm, _0_Memory_0.ram, _0.nvm, _0_MockSep_0.tib, _0_MockVariableIntBlock_0.frq, _0_MockSep_0.frq, _0.fdx, _0_MockSep_0.tii, segments_5, _0_MockSep_0.pyl, _0.fdt]
[junit4:junit4] 2> 28696 T2716 C180 P52256 oass.SolrIndexSearcher.<init> Opening Searcher@7ae2a774 main
[junit4:junit4] 2> 28697 T2716 C180 P52256 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 28698 T2723 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7ae2a774 main{StandardDirectoryReader(segments_4:3:nrt _0(4.3):C2)}
[junit4:junit4] 2> 28699 T2716 C180 P52256 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 63
[junit4:junit4] 2> 28700 T2732 C182 P52260 oass.SolrIndexSearcher.<init> Opening Searcher@4e76c9a0 main
[junit4:junit4] 2> 28701 T2732 C182 P52260 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 28702 T2740 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4e76c9a0 main{StandardDirectoryReader(segments_5:3:nrt _0(4.3):C3)}
[junit4:junit4] 2> 28703 T2732 C182 P52260 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 73
[junit4:junit4] 2> 28741 T2751 C183 P52267 oass.SolrIndexSearcher.<init> Opening Searcher@7a776dd4 main
[junit4:junit4] 2> 28742 T2751 C183 P52267 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 28744 T2759 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a776dd4 main{StandardDirectoryReader(segments_6:3:nrt _0(4.3):C4)}
[junit4:junit4] 2> 28744 T2751 C183 P52267 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 102
[junit4:junit4] 2> 28745 T2698 C181 P52253 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 147
[junit4:junit4] 2> 28746 T2663 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 28748 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 28749 T2663 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 28754 T2701 C181 P52253 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 28757 T2717 C180 P52256 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 28761 T2733 C182 P52260 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=1
[junit4:junit4] 2> 28765 T2752 C183 P52267 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 28769 T2663 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 28784 T2729 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 28786 T2729 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 28799 T2696 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 28800 T2696 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52253/collection1/
[junit4:junit4] 2> 28800 T2696 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52253 START replicas=[http://127.0.0.1:52256/collection1/, http://127.0.0.1:52260/collection1/, http://127.0.0.1:52267/collection1/] nUpdates=100
[junit4:junit4] 2> 28807 T2713 C180 P52256 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 28808 T2753 C183 P52267 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 28809 T2696 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52253 Received 3 versions from 127.0.0.1:52256/collection1/
[junit4:junit4] 2> 28810 T2696 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52253 Our versions are newer. ourLowThreshold=1429606434583085056 otherHigh=1429606434648096768
[junit4:junit4] 2> 28810 T2730 C182 P52260 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 28811 T2696 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52253 Received 5 versions from 127.0.0.1:52267/collection1/
[junit4:junit4] 2> 28811 T2696 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52253 Our versions are newer. ourLowThreshold=1429606434583085056 otherHigh=1429606434676408320
[junit4:junit4] 2> 28812 T2696 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52253 Received 4 versions from 127.0.0.1:52260/collection1/
[junit4:junit4] 2> 28812 T2696 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52253 Our versions are newer. ourLowThreshold=1429606434583085056 otherHigh=1429606434676408320
[junit4:junit4] 2> 28813 T2696 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52253 DONE. sync succeeded
[junit4:junit4] 2> 28813 T2696 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 28814 T2696 oasc.SyncStrategy.syncToMe http://127.0.0.1:52253/collection1/: try and ask http://127.0.0.1:52256/collection1/ to sync
[junit4:junit4] 2> 28815 T2696 oasc.SyncStrategy.syncToMe http://127.0.0.1:52253/collection1/: try and ask http://127.0.0.1:52260/collection1/ to sync
[junit4:junit4] 2> 28816 T2696 oasc.SyncStrategy.syncToMe http://127.0.0.1:52253/collection1/: try and ask http://127.0.0.1:52267/collection1/ to sync
[junit4:junit4] 2> 28821 T2714 C180 P52256 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52256 START replicas=[http://127.0.0.1:52253/collection1/] nUpdates=100
[junit4:junit4] 2> 28824 T2731 C182 P52260 oasu.PeerSync.sync PeerSync: core=collection1 url
[...truncated too long message...]
2> 7221073 T6197 oas.SolrTestCaseJ4.tearDown ###Ending testBackCompatXml
[junit4:junit4] 2> 7221075 T6197 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 7223100 T6196 ccr.ThreadLeakControl.tryToInterruptAll SEVERE There are still zombie threads that couldn't be terminated:
[junit4:junit4] 2> 1) Thread[id=6202, name=searcherExecutor-3777-thread-1, state=WAITING, group=TGRP-TestSolrDiscoveryProperties]
[junit4:junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4:junit4] 2> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
[junit4:junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
[junit4:junit4] 2> at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:957)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:917)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:680)
[junit4:junit4] 2> 2) Thread[id=6197, name=SUITE-TestSolrDiscoveryProperties-seed#[B2B53A5D6707D199]-worker, state=TIMED_WAITING, group=TGRP-TestSolrDiscoveryProperties]
[junit4:junit4] 2> at java.lang.Thread.sleep(Native Method)
[junit4:junit4] 2> at org.apache.solr.SolrTestCaseJ4.endTrackingSearchers(SolrTestCaseJ4.java:231)
[junit4:junit4] 2> at org.apache.solr.SolrTestCaseJ4.afterClass(SolrTestCaseJ4.java:97)
[junit4:junit4] 2> at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
[junit4:junit4] 2> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[junit4:junit4] 2> at java.lang.reflect.Method.invoke(Method.java:597)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:700)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:680)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=hu, timezone=BST
[junit4:junit4] 2> NOTE: Mac OS X 10.8.2 x86_64/Apple Inc. 1.6.0_41 (64-bit)/cpus=2,threads=6,free=478503816,total=532545536
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestStressLucene, BadComponentTest, WordBreakSolrSpellCheckerTest, DirectSolrSpellCheckerTest, TestWriterPerf, BasicDistributedZkTest, ConvertedLegacyTest, JSONWriterTest, TestCopyFieldCollectionResource, TestCollationKeyRangeQueries, TestLFUCache, TestReload, ClusterStateTest, IndexReaderFactoryTest, ShardRoutingTest, QueryElevationComponentTest, SuggesterTSTTest, TestReversedWildcardFilterFactory, DOMUtilTest, DirectUpdateHandlerOptimizeTest, TestJmxMonitoredMap, SolrCmdDistributorTest, ChaosMonkeySafeLeaderTest, TestArbitraryIndexDir, UpdateParamsTest, PreAnalyzedFieldTest, DateFieldTest, TestSolrQueryParser, TestUtils, DistributedSpellCheckComponentTest, UnloadDistributedZkTest, TestFastLRUCache, TestPropInjectDefaults, TestRTGBase, LoggingHandlerTest, TimeZoneUtilsTest, TestStressVersions, TestLMJelinekMercerSimilarityFactory, CSVRequestHandlerTest, FastVectorHighlighterTest, TestValueSourceCache, TestLazyCores, TestQuerySenderListener, TestLRUCache, SuggesterWFSTTest, TestSuggestSpellingConverter, XsltUpdateRequestHandlerTest, ShowFileRequestHandlerTest, TestPropInject, ZkSolrClientTest, PingRequestHandlerTest, TestTrie, SampleTest, TestFastWriter, SpellCheckComponentTest, BasicDistributedZk2Test, TestDistributedGrouping, DirectUpdateHandlerTest, TestWordDelimiterFilterFactory, SpellingQueryConverterTest, TestAnalyzedSuggestions, TestShardHandlerFactory, TestBinaryResponseWriter, UpdateRequestProcessorFactoryTest, SolrPluginUtilsTest, UUIDFieldTest, TestFieldCollectionResource, TestSolrDeletionPolicy2, TermsComponentTest, LeaderElectionIntegrationTest, DistributedTermsComponentTest, UniqFieldsUpdateProcessorFactoryTest, TestCharFilters, DistributedQueryElevationComponentTest, CopyFieldTest, TestXIncludeConfig, IndexBasedSpellCheckerTest, PrimUtilsTest, RequiredFieldsTest, LukeRequestHandlerTest, TestBinaryField, TestPseudoReturnFields, JsonLoaderTest, SolrIndexConfigTest, TestBadConfig, TestFuzzyAnalyzedSuggestions, CurrencyFieldXmlFileTest, TestNumberUtils, SpatialFilterTest, SynonymTokenizerTest, SearchHandlerTest, SyncSliceTest, SoftAutoCommitTest, OverseerTest, TestRandomFaceting, SolrTestCaseJ4Test, LeaderElectionTest, SOLR749Test, SpellCheckCollatorTest, SliceStateUpdateTest, TestConfig, PathHierarchyTokenizerFactoryTest, BasicZkTest, TestElisionMultitermQuery, TestExtendedDismaxParser, CoreAdminHandlerTest, TestIndexingPerformance, TestDistributedSearch, TestQueryUtils, NumericFieldsTest, PrimitiveFieldTypeTest, LegacyHTMLStripCharFilterTest, TestFoldingMultitermQuery, TestSolrXMLSerializer, TestRandomDVFaceting, ReturnFieldsTest, ResponseLogComponentTest, TestFieldResource, CoreContainerCoreInitFailuresTest, ShardRoutingCustomTest, FileBasedSpellCheckerTest, TestDocSet, OverseerCollectionProcessorTest, TestHashPartitioner, DirectSolrConnectionTest, SimpleFacetsTest, TestFaceting, TestCoreContainer, TestQueryTypes, CollectionsAPIDistributedZkTest, OpenCloseCoreStressTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, TestReplicationHandler, ClusterStateUpdateTest, TestZkChroot, ZkCLITest, AutoCommitTest, TestRecovery, TermVectorComponentDistributedTest, ZkControllerTest, TestRealTimeGet, TestStressReorder, TestJoin, TestMultiCoreConfBootstrap, HardAutoCommitTest, TestRangeQuery, TestSolr4Spatial, SolrCoreTest, StatsComponentTest, TestGroupingSearch, PeerSyncTest, BadIndexSchemaTest, TestSort, TestFiltering, TestFunctionQuery, BasicFunctionalityTest, TestIndexSearcher, HighlighterTest, CurrencyFieldOpenExchangeTest, SolrIndexSplitterTest, SimplePostToolTest, TestSolrDiscoveryProperties]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestSolrDiscoveryProperties -Dtests.seed=B2B53A5D6707D199 -Dtests.slow=true -Dtests.locale=hu -Dtests.timezone=BST -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 0.00s | TestSolrDiscoveryProperties (suite) <<<
[junit4:junit4] > Throwable #1: java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([B2B53A5D6707D199]:0)
[junit4:junit4] Completed in 7223.14s, 2 tests, 2 errors <<< FAILURES!
[...truncated 317 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:381: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:361: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:183: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:449: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1213: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:877: There were test failures: 273 suites, 1145 tests, 1 suite-level error, 1 error, 1 failure, 374 ignored (5 assumptions)
Total time: 194 minutes 37 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.6.0 -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure