lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3852 - Failure
Date Tue, 02 Apr 2013 14:29:57 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3852/

1 tests failed.
REGRESSION:  org.apache.solr.cloud.SyncSliceTest.testDistribSearch

Error Message:
shard1 is not consistent.  Got 305 from http://127.0.0.1:16614/collection1lastClient and got 5 from http://127.0.0.1:35055/collection1

Stack Trace:
java.lang.AssertionError: shard1 is not consistent.  Got 305 from http://127.0.0.1:16614/collection1lastClient and got 5 from http://127.0.0.1:35055/collection1
	at __randomizedtesting.SeedInfo.seed([70332693A9C0EF0D:F1D5A88BDE9F8F31]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)




Build Log:
[...truncated 9833 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.050; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.056; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.058; org.apache.solr.cloud.ZkTestServer; STARTING ZK TEST SERVER
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.058; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.062; org.apache.zookeeper.server.ZooKeeperServer; tickTime set to 1000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.062; org.apache.zookeeper.server.ZooKeeperServer; minSessionTimeout set to -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.062; org.apache.zookeeper.server.ZooKeeperServer; maxSessionTimeout set to -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.063; org.apache.zookeeper.server.NIOServerCnxnFactory; binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.064; org.apache.zookeeper.server.persistence.FileTxnSnapLog; Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1364912100057/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.159; org.apache.solr.cloud.ZkTestServer; start zk server on port:28063
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.159; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@197dc513
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.160; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.161; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.161; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.162; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:34670
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.163; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:34670
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.163; org.apache.zookeeper.server.persistence.FileTxnLog; Creating new log file: log.1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.167; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10000 with negotiated timeout 10000 for client /140.211.11.196:34670
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.167; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10000, negotiated timeout = 10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.168; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@197dc513 name:ZooKeeperConnection Watcher:127.0.0.1:28063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.168; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.168; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.172; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.181; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e10000 closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.181; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:34670 which had sessionid 0x13dcb19d2e10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.181; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.182; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@79750355
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.183; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.183; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.184; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.184; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:16806
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.185; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:16806
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.186; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10001 with negotiated timeout 10000 for client /140.211.11.196:16806
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.186; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10001, negotiated timeout = 10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.187; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@79750355 name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.187; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.188; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.192; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.201; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.205; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.208; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.209; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.222; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.223; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.352; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.353; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.356; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.357; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.366; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.367; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.370; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.371; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.374; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.375; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.378; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.379; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.382; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.383; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.386; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e10001
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.387; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e10001 closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.387; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:16806 which had sessionid 0x13dcb19d2e10001
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.387; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.612; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.618; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:17400
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.619; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.619; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.620; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.620; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/solr.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.621; org.apache.solr.core.CoreContainer; New CoreContainer 1978975758
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.622; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.622; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.703; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.704; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.704; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.705; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.705; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.706; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.706; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.707; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.708; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.708; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.733; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.756; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:28063/solr
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.757; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.758; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3661a669
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.759; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.760; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.761; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.762; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:36317
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.762; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:36317
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.764; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10002 with negotiated timeout 20000 for client /140.211.11.196:36317
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.764; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10002, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.765; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3661a669 name:ZooKeeperConnection Watcher:127.0.0.1:28063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.765; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.767; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e10002
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.768; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e10002 closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.768; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:36317 which had sessionid 0x13dcb19d2e10002
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.768; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.769; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.782; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1f2d959b
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.783; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.783; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.784; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.784; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:32287
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.785; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:32287
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.786; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10003 with negotiated timeout 20000 for client /140.211.11.196:32287
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.786; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10003, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.787; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1f2d959b name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.787; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.790; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.798; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.800; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.803; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.811; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:17400_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.812; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:17400_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:17400_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.813; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:17400_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.817; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.830; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.831; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.838; org.apache.solr.cloud.Overseer; Overseer (id=89450879389859843-127.0.0.1:17400_-n_0000000000) starting
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.839; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.841; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.843; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.845; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.854; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.856; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.856; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.859; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.866; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.870; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.873; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.874; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.875; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.875; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.877; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/collection1/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.878; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/collection1/lib/classes/' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.878; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/collection1/lib/README' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.931; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:00.995; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.097; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.103; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.752; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.760; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.763; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.775; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.779; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.783; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:01.784; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:01.784; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.784; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:01.785; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:01.786; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.786; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.786; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1364912100388/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1364912100057/control/data/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.786; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@737e435a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.787; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.788; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/control/data
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.788; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1364912100057/control/data/index/
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:01.789; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1364912100057/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.790; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/control/data/index
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.800; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/control/data/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.800; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.802; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.803; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.803; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.804; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.804; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.804; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.805; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.805; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.805; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.814; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.819; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5e87c3fe main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.820; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.820; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.823; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5e87c3fe main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.824; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:01.825; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.375; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.376; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"1",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":null,
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"down",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"control_collection",
[junit4:junit4]   1>   "node_name":"127.0.0.1:17400_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:17400"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.376; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.376; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard shard=shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.389; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.827; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.827; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:17400 collection:control_collection shard:shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.828; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.845; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:delete cxid:0x83 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.851; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.852; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x84 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.855; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.856; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.856; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:17400/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.856; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.857; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:17400/collection1/ has no replicas
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.857; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:17400/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.857; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:02.862; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10003 type:create cxid:0x8f zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:03.894; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:03.991; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.047; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:17400/collection1/ and leader is http://127.0.0.1:17400/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.047; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:17400
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.047; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.048; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.048; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.053; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.054; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.055; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.056; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.070; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.071; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6bda358d
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.072; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.073; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.073; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.074; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:21672
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.074; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:21672
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.076; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10004 with negotiated timeout 10000 for client /140.211.11.196:21672
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.076; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10004, negotiated timeout = 10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.076; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@6bda358d name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.076; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.079; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.081; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.288; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.291; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:63669
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.292; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.293; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.293; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.294; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/solr.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.294; org.apache.solr.core.CoreContainer; New CoreContainer 1180815922
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.295; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.296; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.362; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.363; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.364; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.364; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.365; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.366; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.366; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.367; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.367; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.368; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.388; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.410; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:28063/solr
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.411; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.411; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3136b12d
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.412; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.413; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.414; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.414; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:39435
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.415; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:39435
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.416; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10005 with negotiated timeout 20000 for client /140.211.11.196:39435
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.416; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10005, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.417; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3136b12d name:ZooKeeperConnection Watcher:127.0.0.1:28063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.417; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.419; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e10005
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.420; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e10005 closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.420; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:39435 which had sessionid 0x13dcb19d2e10005
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.420; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.421; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.432; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1163b26a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.433; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.433; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.434; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.434; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:13222
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.434; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:13222
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.436; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10006 with negotiated timeout 20000 for client /140.211.11.196:13222
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.436; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10006, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.436; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@1163b26a name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.437; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.438; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.440; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:04.448; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.451; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63669_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.453; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63669_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63669_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.475; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:63669_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.478; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.479; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.479; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.481; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.495; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.495; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.496; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.497; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.498; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/collection1/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.499; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.500; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"1",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"active",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"control_collection",
[junit4:junit4]   1>   "node_name":"127.0.0.1:17400_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:17400"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.500; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/collection1/lib/classes/' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.501; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/collection1/lib/README' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.511; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.511; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.511; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.562; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.636; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.737; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:05.744; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.390; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.401; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.405; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.418; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.423; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.427; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:06.428; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:06.429; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.429; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:06.431; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:06.431; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.431; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.432; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1364912104081/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.432; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@737e435a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.433; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.433; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.434; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index/
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:06.435; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.435; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.440; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.440; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.443; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.443; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.444; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.444; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.445; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.445; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.446; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.446; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.447; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.458; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.465; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@4d705aa1 main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.466; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.466; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.470; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@4d705aa1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.472; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:06.472; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.016; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.017; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"2",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":null,
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"down",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:63669_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:63669"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.018; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.018; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard shard=shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.030; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.030; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.030; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.474; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.474; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:63669 collection:collection1 shard:shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.475; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.490; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10006 type:delete cxid:0x4b zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.491; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.492; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10006 type:create cxid:0x4c zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.502; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.502; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.503; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:63669/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.503; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.503; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:63669/collection1/ has no replicas
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.504; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:63669/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.504; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:07.508; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10006 type:create cxid:0x57 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.535; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.560; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.560; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.560; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.582; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:63669/collection1/ and leader is http://127.0.0.1:63669/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.582; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63669
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.583; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.583; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.583; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.586; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.587; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.589; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.590; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.915; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.919; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:44659
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.920; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.920; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.921; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.921; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/solr.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.922; org.apache.solr.core.CoreContainer; New CoreContainer 732243788
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.923; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:08.923; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.025; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.026; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.027; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.028; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.029; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.030; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.031; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.032; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.033; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.034; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.061; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.088; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:28063/solr
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.089; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.090; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@324bf163
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.091; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.091; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.093; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.093; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:52143
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.094; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:52143
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.149; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10007 with negotiated timeout 20000 for client /140.211.11.196:52143
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.149; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10007, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.150; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@324bf163 name:ZooKeeperConnection Watcher:127.0.0.1:28063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.150; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.153; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e10007
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.199; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:52143 which had sessionid 0x13dcb19d2e10007
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.200; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e10007 closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.200; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.201; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.213; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@13d79b28
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.215; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.215; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.216; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.216; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:18389
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.217; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:18389
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.219; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10008 with negotiated timeout 20000 for client /140.211.11.196:18389
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.219; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10008, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.219; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@13d79b28 name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.220; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.221; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.236; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:09.247; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.075; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.076; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"2",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"active",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:63669_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:63669"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.091; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.091; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.091; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.091; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.251; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44659_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.252; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e10008 type:delete cxid:0xf zxid:0x72 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:44659_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:44659_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.253; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:44659_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.256; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.256; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.256; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.256; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.257; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.257; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.265; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.265; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.271; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.271; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.272; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.272; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.274; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/collection1/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.275; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/collection1/lib/README' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.275; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/collection1/lib/classes/' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.327; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.390; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.491; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:10.497; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.151; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.163; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.167; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.182; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.187; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.192; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:11.193; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:11.194; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.194; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:11.195; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:11.196; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.196; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.197; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1364912108611/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.197; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@737e435a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.198; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.199; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.199; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index/
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:11.200; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.201; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.206; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.206; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.209; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.209; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.210; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.211; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.212; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.212; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.212; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.213; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.214; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.226; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.234; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1964990d main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.235; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.236; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.240; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1964990d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.242; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.243; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.597; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.598; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"3",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":null,
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"down",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:44659_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:44659"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.598; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.598; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard shard=shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.612; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.612; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.612; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:11.612; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.245; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.245; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:44659 collection:collection1 shard:shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.249; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:44659/collection1/ and leader is http://127.0.0.1:63669/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.249; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44659
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.250; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.250; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.251; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.251; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.252; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.253; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.253; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.253; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.254; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.254; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.255; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.475; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.478; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:16614
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.479; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.479; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.480; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.480; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/solr.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.481; org.apache.solr.core.CoreContainer; New CoreContainer 277026890
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.482; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.482; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.548; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.549; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.550; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.550; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.551; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.552; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.552; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.553; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.553; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.554; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.574; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.595; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:28063/solr
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.596; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.597; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3d0cb28a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.598; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.599; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.600; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.600; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:61618
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.601; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:61618
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.603; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e10009 with negotiated timeout 20000 for client /140.211.11.196:61618
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.603; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e10009, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.603; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@3d0cb28a name:ZooKeeperConnection Watcher:127.0.0.1:28063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.604; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.605; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e10009
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.614; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e10009 closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.614; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:61618 which had sessionid 0x13dcb19d2e10009
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.614; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.614; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.625; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5fb9b06d
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.626; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.627; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.627; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.628; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:35043
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.628; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:35043
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.629; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e1000a with negotiated timeout 20000 for client /140.211.11.196:35043
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.629; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e1000a, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.630; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@5fb9b06d name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.630; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.631; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e1000a type:create cxid:0x1 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.634; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e1000a type:create cxid:0x3 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:12.641; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.117; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.118; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"3",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"recovering",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:44659_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:44659"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.131; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.131; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.131; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.131; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.131; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.273; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:44659_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.645; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16614_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.646; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e1000a type:delete cxid:0xf zxid:0x85 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:16614_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:16614_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.648; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:16614_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.651; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.651; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.651; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.651; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.656; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.656; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.658; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.658; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.658; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.658; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.668; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.668; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.669; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.669; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.671; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/collection1/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.672; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/collection1/lib/README' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.673; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/collection1/lib/classes/' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.726; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.788; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.890; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:13.896; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.544; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.556; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.560; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.575; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.580; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.585; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:14.586; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:14.587; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.587; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:14.588; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:14.589; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.589; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.590; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1364912112271/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.590; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@737e435a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.591; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.591; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.592; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index/
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:14.593; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.594; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.624; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.625; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.628; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.628; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.629; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.630; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.630; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.631; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.631; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.632; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.632; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.645; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.653; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@22e93caa main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.654; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.654; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.659; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@22e93caa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.661; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:14.661; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.275; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:63669/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.275; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:44659 START replicas=[http://127.0.0.1:63669/collection1/] nUpdates=100
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:15.276; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.277; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.277; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.277; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.278; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.278; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:63669/collection1/. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.278; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.284; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.293; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.298; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.299; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.304; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.305; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.307; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@28ea055e realtime
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.307; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.308; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 15
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.308; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for  10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.309; org.apache.solr.handler.SnapPuller;  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.311; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for  10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.311; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.312; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.312; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.313; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.316; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.317; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.318; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index.20130403011515317
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.319; org.apache.solr.handler.SnapPuller; Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index.20130403011515317 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7440a096 fullCopy=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.322; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.324; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.326; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.326; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.331; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.331; org.apache.solr.core.SolrDeletionPolicy; newest commit = 2[segments_2]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.332; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.332; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@e4242e4 main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.334; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@e4242e4 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.334; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index.20130403011515317 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index.20130403011515317;done=true>>]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.335; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index.20130403011515317
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.335; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty2/index.20130403011515317
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.336; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.336; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.337; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.337; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:15.339; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.139; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.140; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"4",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":null,
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"down",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:16614_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:16614"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.140; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.140; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard shard=shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.144; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"3",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"active",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:44659_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:44659"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.156; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.156; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.156; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.156; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.156; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.665; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.665; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:16614 collection:collection1 shard:shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.671; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:16614/collection1/ and leader is http://127.0.0.1:63669/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.671; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16614
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.672; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.672; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.673; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.673; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.674; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.674; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.674; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.675; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.676; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.676; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.676; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.901; org.eclipse.jetty.server.Server; jetty-8.1.8.v20121106
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.904; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:35055
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.905; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.906; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.906; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.907; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/solr.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.908; org.apache.solr.core.CoreContainer; New CoreContainer 274073280
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.908; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.909; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.977; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.978; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.979; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.980; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.980; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.981; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.981; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.982; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.983; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:16.983; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.004; org.apache.solr.core.CoreContainer; Registering Log Listener
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.026; org.apache.solr.core.CoreContainer; Zookeeper client=127.0.0.1:28063/solr
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.027; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.028; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@788b7de5
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.029; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.029; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.031; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.031; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:35066
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.031; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:35066
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.033; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e1000b with negotiated timeout 20000 for client /140.211.11.196:35066
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.033; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e1000b, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.034; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@788b7de5 name:ZooKeeperConnection Watcher:127.0.0.1:28063 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.034; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.038; org.apache.zookeeper.server.PrepRequestProcessor; Processed session termination for sessionid: 0x13dcb19d2e1000b
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.044; org.apache.zookeeper.ZooKeeper; Session: 0x13dcb19d2e1000b closed
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.044; org.apache.zookeeper.server.NIOServerCnxn; Closed socket connection for client /140.211.11.196:35066 which had sessionid 0x13dcb19d2e1000b
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.044; org.apache.zookeeper.ClientCnxn$EventThread; EventThread shut down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.045; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.058; org.apache.zookeeper.ZooKeeper; Initiating client connection, connectString=127.0.0.1:28063/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2eef3212
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.059; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.060; org.apache.zookeeper.ClientCnxn$SendThread; Opening socket connection to server localhost/127.0.0.1:28063. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.060; org.apache.zookeeper.ClientCnxn$SendThread; Socket connection established to localhost/127.0.0.1:28063, initiating session
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.061; org.apache.zookeeper.server.NIOServerCnxnFactory; Accepted socket connection from /140.211.11.196:35069
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.061; org.apache.zookeeper.server.ZooKeeperServer; Client attempting to establish new session at /140.211.11.196:35069
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.063; org.apache.zookeeper.server.ZooKeeperServer; Established session 0x13dcb19d2e1000c with negotiated timeout 20000 for client /140.211.11.196:35069
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.063; org.apache.zookeeper.ClientCnxn$SendThread; Session establishment complete on server localhost/127.0.0.1:28063, sessionid = 0x13dcb19d2e1000c, negotiated timeout = 20000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.063; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2eef3212 name:ZooKeeperConnection Watcher:127.0.0.1:28063/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.064; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.065; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e1000c type:create cxid:0x1 zxid:0x96 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.067; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e1000c type:create cxid:0x3 zxid:0x97 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.075; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.671; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.672; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"4",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"recovering",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:16614_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:16614"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.706; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.706; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.706; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.706; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.706; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:17.706; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.087; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35055_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.088; org.apache.zookeeper.server.PrepRequestProcessor; Got user-level KeeperException when processing sessionid:0x13dcb19d2e1000c type:delete cxid:0xf zxid:0x9c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:35055_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:35055_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.090; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:35055_
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.092; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.092; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.092; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.092; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.092; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.093; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.095; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.096; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.096; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.099; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.099; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.101; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.107; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.108; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.109; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.109; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.112; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/collection1/'
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.114; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/collection1/lib/README' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.115; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/collection1/lib/classes/' to classloader
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.180; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.256; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.358; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.367; org.apache.solr.schema.IndexSchema; Schema name=test
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.696; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:16614_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:18.997; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.009; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.015; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.030; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.035; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.040; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:19.041; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:19.042; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.042; org.apache.solr.schema.OpenExchangeRatesOrgProvider; Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:19.043; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Unknown key IMPORTANT NOTE
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:19.043; org.apache.solr.schema.OpenExchangeRatesOrgProvider$OpenExchangeRates; Expected key, got STRING
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.044; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.044; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1364912116692/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.044; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@737e435a
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.045; org.apache.solr.core.SolrCore; solr.StandardDirectoryFactory
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.046; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.047; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index/
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:19.047; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.048; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.072; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.072; org.apache.solr.core.SolrDeletionPolicy; newest commit = 1[segments_1]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.075; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.076; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.076; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.077; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.078; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.078; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.078; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.079; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.079; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.092; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.100; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@71378e02 main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.101; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.101; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.105; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@71378e02 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.107; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.107; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.221; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.222; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"5",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":null,
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"down",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:35055_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:35055"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.222; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.222; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard shard=shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.227; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.227; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.227; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.227; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.227; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:19.227; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.111; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.111; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:35055 collection:collection1 shard:shard1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.120; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:35055/collection1/ and leader is http://127.0.0.1:63669/collection1/
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.121; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35055
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.121; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.121; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.122; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.122; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.123; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.124; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.124; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.124; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.125; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.126; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.138; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.144; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.146; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.146; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.147; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.698; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:63669/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.698; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:16614 START replicas=[http://127.0.0.1:63669/collection1/] nUpdates=100
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:20.699; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.700; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.700; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.700; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.700; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.701; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:63669/collection1/. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.701; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.701; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.714; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.731; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.732; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"5",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"recovering",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:35055_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:35055"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.756; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.756; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.758; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 44
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.761; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for  10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.762; org.apache.solr.handler.SnapPuller;  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.764; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.765; org.apache.solr.handler.SnapPuller; Master's generation: 3
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.765; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.765; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.769; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.769; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.771; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index.20130403011520770
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.772; org.apache.solr.handler.SnapPuller; Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index.20130403011520770 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3d859d1f fullCopy=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.775; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.777; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.787; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.787; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.791; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index,segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.792; org.apache.solr.core.SolrDeletionPolicy; newest commit = 3[segments_3]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.793; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.794; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@30e0d390 main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.795; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@30e0d390 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.795; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index.20130403011520770 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index.20130403011520770;done=true>>]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.796; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index.20130403011520770
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.796; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty3/index.20130403011520770
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.797; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.797; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.798; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.798; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:20.800; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:21.149; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:21.152; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:35055_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.152; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.269; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.270; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"4",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"active",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:16614_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:16614"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.312; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.312; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.312; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.312; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.312; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:22.312; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.154; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:63669/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.154; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:35055 START replicas=[http://127.0.0.1:63669/collection1/] nUpdates=100
[junit4:junit4]   1> WARN  - 2013-04-02 14:15:23.155; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.155; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.155; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.155; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.157; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.157; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.157; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:63669/collection1/. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.157; org.apache.solr.core.SolrCore; [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.157; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.173; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.197; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty1/index,segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.197; org.apache.solr.core.SolrDeletionPolicy; newest commit = 4[segments_4]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.198; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.199; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.200; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for  10000
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.200; org.apache.solr.handler.SnapPuller;  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.202; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.203; org.apache.solr.handler.SnapPuller; Master's generation: 4
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.203; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.203; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.207; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.207; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.209; org.apache.solr.core.CachingDirectoryFactory; return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index.20130403011523208
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.210; org.apache.solr.handler.SnapPuller; Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index.20130403011523208 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f5f5cbd fullCopy=false
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.213; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.215; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.217; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.217; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.221; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   1> 	commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index,segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.222; org.apache.solr.core.SolrDeletionPolicy; newest commit = 4[segments_4]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.223; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.224; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1e9c0bba main
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.225; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1e9c0bba main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.225; org.apache.solr.core.CachingDirectoryFactory; looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index.20130403011523208 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index.20130403011523208;done=true>>]
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.226; org.apache.solr.core.CachingDirectoryFactory; Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index.20130403011523208
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.226; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1364912100057/jetty4/index.20130403011523208
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.227; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.227; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.228; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.228; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.229; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.825; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper... 
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.826; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4]   1>   "operation":"state",
[junit4:junit4]   1>   "core_node_name":"5",
[junit4:junit4]   1>   "numShards":"1",
[junit4:junit4]   1>   "shard":"shard1",
[junit4:junit4]   1>   "roles":null,
[junit4:junit4]   1>   "state":"active",
[junit4:junit4]   1>   "core":"collection1",
[junit4:junit4]   1>   "collection":"collection1",
[junit4:junit4]   1>   "node_name":"127.0.0.1:35055_",
[junit4:junit4]   1>   "base_url":"http://127.0.0.1:35055"}
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.929; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.929; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.929; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   1> INFO  - 2013-04-02 14:15:23.929; org.apache.solr.common.cloud.ZkStateReader$2; A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live 

[...truncated too long message...]

99463936}, {id=275, _version_=1431214541358759936}, {id=107, _version_=1431214539013095424}, {id=97, _version_=1431214538873634816}, {id=193, _version_=1431214540235735040}, {id=269, _version_=1431214541274873856}, {id=98, _version_=1431214538887266304}, {id=39, _version_=1431214538083008512}, {id=232, _version_=1431214540763168768}, {id=165, _version_=1431214539875024896}, {id=76, _version_=1431214538588422144}, {id=207, _version_=1431214540416090112}, {id=302, _version_=1431214541747781632}, {id=263, _version_=1431214541190987776}, {id=133, _version_=1431214539366465536}, {id=249, _version_=1431214540997001216}, {id=294, _version_=1431214541641875456}, {id=230, _version_=1431214540733808640}, {id=234, _version_=1431214540790431744}, {id=248, _version_=1431214540983369728}, {id=63, _version_=1431214538411212800}, {id=10, _version_=1431214537681403904}, {id=7, _version_=1431214537640509440}, {id=64, _version_=1431214538424844288}, {id=202, _version_=1431214540352126976}, {id=65, _version_=1431214538438475776}, {id=213, _version_=1431214540493684736}, {id=77, _version_=1431214538602053632}, {id=301, _version_=1431214541734150144}, {id=31, _version_=1431214537973956608}, {id=48, _version_=1431214538206740480}, {id=235, _version_=1431214540804063232}, {id=180, _version_=1431214540066914304}, {id=280, _version_=1431214541449986048}, {id=278, _version_=1431214541398605824}, {id=191, _version_=1431214540208472064}, {id=140, _version_=1431214539459788800}, {id=128, _version_=1431214539298308096}, {id=42, _version_=1431214538123902976}, {id=28, _version_=1431214537933062144}, {id=80, _version_=1431214538640850944}, {id=33, _version_=1431214538001219584}, {id=79, _version_=1431214538627219456}, {id=134, _version_=1431214539380097024}, {id=122, _version_=1431214539217567744}, {id=34, _version_=1431214538014851072}, {id=94, _version_=1431214538833788928}, {id=219, _version_=1431214540576522240}, {id=243, _version_=1431214540915212288}, {id=71, _version_=1431214538520264704}, {id=121, _version_=1431214539203936256}, {id=244, _version_=1431214540928843776}, {id=11, _version_=1431214537695035392}, {id=246, _version_=1431214540956106752}, {id=105, _version_=1431214538985832448}, {id=62, _version_=1431214538397581312}, {id=171, _version_=1431214539952619520}, {id=277, _version_=1431214541384974336}, {id=242, _version_=1431214540901580800}, {id=178, _version_=1431214540041748480}, {id=170, _version_=1431214539938988032}, {id=203, _version_=1431214540364709888}, {id=227, _version_=1431214540690817024}, {id=60, _version_=1431214538370318336}, {id=195, _version_=1431214540261949440}, {id=61, _version_=1431214538383949824}, {id=222, _version_=1431214540618465280}, {id=30, _version_=1431214537960325120}, {id=86, _version_=1431214538722639872}, {id=113, _version_=1431214539094884352}, {id=54, _version_=1431214538288529408}, {id=146, _version_=1431214539542626304}, {id=120, _version_=1431214539190304768}, {id=250, _version_=1431214541010632704}, {id=21, _version_=1431214537837641728}, {id=236, _version_=1431214540816646144}, {id=155, _version_=1431214539667406848}, {id=150, _version_=1431214539597152256}, {id=19, _version_=1431214537810378752}, {id=200, _version_=1431214540326961152}, {id=149, _version_=1431214539583520768}, {id=282, _version_=1431214541477249024}, {id=46, _version_=1431214538179477504}, {id=148, _version_=1431214539569889280}, {id=20, _version_=1431214537824010240}, {id=156, _version_=1431214539681038336}, {id=276, _version_=1431214541371342848}, {id=104, _version_=1431214538972200960}, {id=22, _version_=1431214537851273216}, {id=125, _version_=1431214539257413632}, {id=192, _version_=1431214540222103552}, {id=297, _version_=1431214541680672768}, {id=45, _version_=1431214538165846016}, {id=78, _version_=1431214538613587968}, {id=289, _version_=1431214541572669440}, {id=271, _version_=1431214541303185408}, {id=188, _version_=1431214540170723328}, {id=162, _version_=1431214539833081856}, {id=174, _version_=1431214539990368256}, {id=257, _version_=1431214541106053120}, {id=261, _version_=1431214541161627648}, {id=147, _version_=1431214539556257792}, {id=251, _version_=1431214541024264192}, {id=126, _version_=1431214539271045120}, {id=245, _version_=1431214540942475264}, {id=256, _version_=1431214541092421632}, {id=108, _version_=1431214539026726912}, {id=228, _version_=1431214540705497088}, {id=194, _version_=1431214540248317952}, {id=286, _version_=1431214541531774976}, {id=49, _version_=1431214538220371968}, {id=217, _version_=1431214540549259264}, {id=206, _version_=1431214540403507200}, {id=209, _version_=1431214540442304512}, {id=287, _version_=1431214541545406464}, {id=40, _version_=1431214538096640000}, {id=210, _version_=1431214540455936000}, {id=267, _version_=1431214541246562304}, {id=182, _version_=1431214540093128704}, {id=159, _version_=1431214539722981376}]
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=70332693A9C0EF0D -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=fr_BE -Dtests.timezone=Asia/Sakhalin -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE  883s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: shard1 is not consistent.  Got 305 from http://127.0.0.1:16614/collection1lastClient and got 5 from http://127.0.0.1:35055/collection1
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([70332693A9C0EF0D:F1D5A88BDE9F8F31]:0)
[junit4:junit4]    > 	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:963)
[junit4:junit4]    > 	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   1> INFO  - 2013-04-02 14:29:43.441; org.apache.solr.SolrTestCaseJ4; ###deleteCore
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=Asserting), text=PostingsFormat(name=MockSep), _version_=PostingsFormat(name=Memory doPackFST= false), rnd_b=PostingsFormat(name=TestBloomFilteredLucene41Postings), intDefault=PostingsFormat(name=Memory doPackFST= false), timestamp=PostingsFormat(name=Asserting), id=PostingsFormat(name=TestBloomFilteredLucene41Postings), a_t=PostingsFormat(name=Asserting), range_facet_sl=PostingsFormat(name=TestBloomFilteredLucene41Postings), range_facet_si=PostingsFormat(name=Asserting), other_tl1=PostingsFormat(name=Memory doPackFST= false), multiDefault=PostingsFormat(name=Asserting), a_si=PostingsFormat(name=Memory doPackFST= false)}, docValues:{timestamp=DocValuesFormat(name=Disk)}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=fr_BE, timezone=Asia/Sakhalin
[junit4:junit4]   2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=5,free=202416216,total=452984832
[junit4:junit4]   2> NOTE: All tests run in this JVM: [QueryElevationComponentTest, TestSolrCoreProperties, FastVectorHighlighterTest, LukeRequestHandlerTest, AutoCommitTest, TestJoin, DocumentBuilderTest, TestPseudoReturnFields, TestSearchPerf, TestRealTimeGet, TestQuerySenderListener, TestCharFilters, TestCoreContainer, ShowFileRequestHandlerTest, TestTrie, PreAnalyzedFieldTest, UpdateRequestProcessorFactoryTest, TestValueSourceCache, CircularListTest, SolrIndexSplitterTest, TestSolrDeletionPolicy1, TestSweetSpotSimilarityFactory, SystemInfoHandlerTest, ReturnFieldsTest, SpatialFilterTest, PrimitiveFieldTypeTest, TestRandomDVFaceting, TestSolrQueryParser, DirectUpdateHandlerOptimizeTest, TestPropInjectDefaults, TestExtendedDismaxParser, QueryEqualityTest, BasicFunctionalityTest, SoftAutoCommitTest, TestBadConfig, PeerSyncTest, TestSolrIndexConfig, TestXIncludeConfig, TestReplicationHandler, TestDefaultSearchFieldResource, TestSchemaVersionResource, PluginInfoTest, TestDynamicFieldCollectionResource, TestDynamicFieldResource, ShardRoutingTest, MinimalSchemaTest, DocValuesTest, TestDocumentBuilder, TestPHPSerializedResponseWriter, TestQueryUtils, TestFaceting, TestConfig, SliceStateTest, MBeansHandlerTest, TestLRUCache, TestFastWriter, ClusterStateUpdateTest, SearchHandlerTest, BadComponentTest, ScriptEngineTest, FieldMutatingUpdateProcessorTest, ChaosMonkeyNothingIsSafeTest, RegexBoostProcessorTest, MoreLikeThisHandlerTest, TestCopyFieldCollectionResource, AlternateDirectoryTest, TestSchemaResource, TestManagedSchema, BasicDistributedZkTest, BasicDistributedZk2Test, SyncSliceTest]
[junit4:junit4] Completed on J0 in 883.43s, 1 test, 1 failure <<< FAILURES!

[...truncated 13 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:375: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:355: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:448: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1231: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:875: There were test failures: 284 suites, 1171 tests, 1 failure, 27 ignored (8 assumptions)

Total time: 56 minutes 10 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message