You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/11 00:05:32 UTC
[JENKINS] Lucene-Solr-Tests-4.x-java7 - Build # 1230 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-java7/1230/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:39507 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:39507 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([8CF3602EA61B4B22:D15EE36D1442B1E]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
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 9397 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.137; org.apache.solr.BaseDistributedSearchTestCase; Setting hostContext system property: /
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.144; org.apache.solr.SolrTestCaseJ4; ###Starting testDistribSearch
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.146; 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-05-10 21:49:42.146; org.apache.solr.cloud.ZkTestServer$ZKServerMain; Starting server
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.247; org.apache.solr.cloud.ZkTestServer; start zk server on port:49972
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.248; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.297; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@547b47d3 name:ZooKeeperConnection Watcher:127.0.0.1:49972 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.297; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.298; org.apache.solr.common.cloud.SolrZkClient; makePath: /solr
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.316; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.318; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@549e59e2 name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.318; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.319; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.358; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/shards
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.391; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.437; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/shards
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.459; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.460; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.521; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.522; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.630; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.631; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.644; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.645; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/protwords.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.649; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.649; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.653; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-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-05-10 21:49:42.654; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.657; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.658; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.661; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.662; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.665; org.apache.solr.cloud.AbstractZkTestCase; put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.666; org.apache.solr.common.cloud.SolrZkClient; makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.891; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.897; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:52652
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.897; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.898; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.899; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.899; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/solr.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.900; org.apache.solr.core.CoreContainer; New CoreContainer 1065467294
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.901; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:42.901; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.020; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.021; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.022; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.023; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.023; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.024; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.024; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.025; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.026; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.026; 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-05-10 21:49:43.044; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.045; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:49972/solr
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.046; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.047; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.074; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@236449ac name:ZooKeeperConnection Watcher:127.0.0.1:49972 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.075; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.078; 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-05-10 21:49:43.091; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.093; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@58ff9d4b name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.093; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.095; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.105; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/collection-queue-work
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.109; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.111; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52652_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.119; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:52652_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.122; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/election
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.135; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer_elect/leader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.138; org.apache.solr.cloud.Overseer; Overseer (id=89667835143847939-127.0.0.1:52652_-n_0000000000) starting
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.149; org.apache.solr.common.cloud.SolrZkClient; makePath: /overseer/queue-work
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.159; org.apache.solr.cloud.OverseerCollectionProcessor; Process current queue of collection creations
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.160; org.apache.solr.common.cloud.SolrZkClient; makePath: /clusterstate.json
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.163; org.apache.solr.common.cloud.SolrZkClient; makePath: /aliases.json
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.170; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.177; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.177; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Starting to work on the main queue
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.177; org.apache.solr.cloud.ZkController; Check for collection zkNode:control_collection
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.178; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.179; org.apache.solr.cloud.ZkController; Load collection config from:/collections/control_collection
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.180; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/collection1/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.182; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.182; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.234; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.296; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.398; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.404; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.971; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.975; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.977; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:43.983; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.009; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.009; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368222582676/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/control/data/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.010; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.010; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.011; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/control/data
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.012; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368222582145/control/data/index/
[junit4:junit4] 1> WARN - 2013-05-10 21:49:44.012; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368222582145/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.013; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/control/data/index
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.016; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3724125a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e83416),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.017; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.020; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.020; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.021; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.022; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.022; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.023; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.023; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.024; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.024; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.037; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.043; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@62ad3c48 main
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.044; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/control/data/tlog
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.045; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.045; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.048; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@62ad3c48 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.051; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.051; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.681; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.682; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:52652_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:52652"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.682; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection control_collection with numShards 1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.683; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:44.731; 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-05-10 21:49:45.074; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.074; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:52652 collection:control_collection shard:shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.075; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.096; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.099; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.100; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.100; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:52652/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.100; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.101; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:52652/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.101; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:52652/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:45.101; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.235; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.257; 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-05-10 21:49:46.289; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:52652/collection1/ and leader is http://127.0.0.1:52652/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.289; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52652
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.289; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.290; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.290; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.293; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.294; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.295; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.295; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.309; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.311; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.313; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@614a251f name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.314; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.316; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.318; org.apache.solr.cloud.ChaosMonkey; monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.530; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.533; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:39507
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.534; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.535; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.535; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.536; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/solr.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.537; org.apache.solr.core.CoreContainer; New CoreContainer 1675321828
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.537; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.538; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.656; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.657; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.658; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.658; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.659; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.659; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.660; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.661; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.661; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.662; 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-05-10 21:49:46.676; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.677; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:49972/solr
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.677; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.679; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.682; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@17b8d00d name:ZooKeeperConnection Watcher:127.0.0.1:49972 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.682; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.702; 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-05-10 21:49:46.713; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.715; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@56ee43bd name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.716; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:46.725; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.729; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39507_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.757; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:39507_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.762; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.762; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.762; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (2)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.763; 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-05-10 21:49:47.779; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.780; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=1 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:52652__collection1",
[junit4:junit4] 1> "numShards":"1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:52652_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:52652"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.785; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.785; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.792; 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-05-10 21:49:47.792; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.792; 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-05-10 21:49:47.793; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.796; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/collection1/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.796; 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-05-10 21:49:47.798; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.798; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.853; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-10 21:49:47.915; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.016; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.022; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.634; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.638; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.640; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.646; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.675; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.676; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368222586319/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.676; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.677; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.677; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.678; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty1/index/
[junit4:junit4] 1> WARN - 2013-05-10 21:49:48.678; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.680; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty1/index
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.684; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59376fee lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bd626c),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.685; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.689; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.689; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.691; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.692; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.693; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.693; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.694; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.694; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.695; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.711; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.718; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@21163bb3 main
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.718; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty1/tlog
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.719; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.720; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.725; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@21163bb3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.727; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-10 21:49:48.728; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.297; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.298; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:39507_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39507"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.299; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Create collection collection1 with numShards 2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.299; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.315; 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-05-10 21:49:49.315; 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-05-10 21:49:49.315; 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-05-10 21:49:49.757; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.757; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:39507 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.758; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.776; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.787; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.787; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.788; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:39507/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.788; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.788; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:39507/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.789; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:39507/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:49.789; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.820; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.874; 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-05-10 21:49:50.874; 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-05-10 21:49:50.874; 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-05-10 21:49:50.918; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:39507/collection1/ and leader is http://127.0.0.1:39507/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.918; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39507
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.918; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.919; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.919; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.922; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.923; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.924; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-10 21:49:50.925; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.176; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.180; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:24039
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.181; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.182; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.183; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.184; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/solr.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.184; org.apache.solr.core.CoreContainer; New CoreContainer 581675096
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.185; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.186; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.310; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.311; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.312; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.312; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.313; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.314; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.314; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.315; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.316; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.316; 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-05-10 21:49:51.334; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.335; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:49972/solr
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.335; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.337; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.340; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@32444e11 name:ZooKeeperConnection Watcher:127.0.0.1:49972 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.340; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.353; 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-05-10 21:49:51.367; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.369; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@2ef4a5ae name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.370; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:51.375; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.379; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24039_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.382; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:24039_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.432; 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-05-10 21:49:52.434; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.434; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.434; 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-05-10 21:49:52.434; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.435; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.435; 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-05-10 21:49:52.437; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.438; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:39507__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:39507_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39507"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.442; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.443; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.501; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.501; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.517; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/collection1/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.519; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.520; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.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: 3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.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: 3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.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: 3)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.564; 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-05-10 21:49:52.595; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.661; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.763; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:52.769; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.397; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.402; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.404; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.410; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.438; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.438; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368222590943/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty2/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.439; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.439; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.440; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.440; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty2/index/
[junit4:junit4] 1> WARN - 2013-05-10 21:49:53.441; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.442; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty2/index
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.445; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@483314d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d45b8d),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.445; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.448; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.449; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.450; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.451; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.451; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.452; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.452; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.453; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.453; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.467; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.474; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@53b4f8d main
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.474; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty2/tlog
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.475; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.476; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.480; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@53b4f8d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.483; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-10 21:49:53.483; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.066; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.067; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:24039_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:24039"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.068; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.068; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.110; 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-05-10 21:49:54.110; 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-05-10 21:49:54.110; 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-05-10 21:49:54.110; 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-05-10 21:49:54.492; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.492; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:24039 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.493; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.509; org.apache.solr.cloud.ShardLeaderElectionContext; Running the leader process.
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.521; org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to continue.
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.521; org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader - try and sync
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.522; org.apache.solr.cloud.SyncStrategy; Sync replicas to http://127.0.0.1:24039/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.522; org.apache.solr.cloud.SyncStrategy; Sync Success - now sync replicas to me
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.522; org.apache.solr.cloud.SyncStrategy; http://127.0.0.1:24039/collection1/ has no replicas
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.523; org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader: http://127.0.0.1:24039/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:54.523; org.apache.solr.common.cloud.SolrZkClient; makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.615; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.659; 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-05-10 21:49:55.660; 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-05-10 21:49:55.660; 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-05-10 21:49:55.660; 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-05-10 21:49:55.710; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:24039/collection1/ and leader is http://127.0.0.1:24039/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.710; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24039
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.710; org.apache.solr.cloud.ZkController; I am the leader, no recovery necessary
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.711; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.711; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.713; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.715; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.716; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.716; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.954; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.958; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:56814
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.959; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.960; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.960; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.961; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/solr.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.962; org.apache.solr.core.CoreContainer; New CoreContainer 1507620951
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.962; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:55.963; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.086; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.087; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.088; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.089; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.089; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.090; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.091; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.091; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.092; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.093; 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-05-10 21:49:56.108; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.109; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:49972/solr
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.109; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.110; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.114; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@369c984 name:ZooKeeperConnection Watcher:127.0.0.1:49972 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.114; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.131; 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-05-10 21:49:56.142; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.144; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@192517fd name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.144; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:56.150; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.154; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56814_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.157; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:56814_
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.160; 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-05-10 21:49:57.161; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.161; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.162; 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-05-10 21:49:57.161; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.161; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.163; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (4)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.162; 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-05-10 21:49:57.163; 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-05-10 21:49:57.174; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.175; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:24039__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:24039_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:24039"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.178; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.179; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.179; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.180; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.188; 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-05-10 21:49:57.188; 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-05-10 21:49:57.188; 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-05-10 21:49:57.188; 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-05-10 21:49:57.188; 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-05-10 21:49:57.189; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/collection1/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.191; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.192; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.253; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.321; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.422; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:57.428; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.024; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.029; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.032; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.038; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.065; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.065; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368222595731/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.066; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.066; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.067; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.067; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index/
[junit4:junit4] 1> WARN - 2013-05-10 21:49:58.068; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.069; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.072; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@535852c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47475be3),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.072; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.075; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.076; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.077; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.077; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.078; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.078; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.079; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.079; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.080; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.093; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.099; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@1f6d808b main
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.099; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/tlog
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.101; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.101; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.106; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@1f6d808b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.109; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.109; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.693; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.694; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:56814_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56814"}
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.694; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.694; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:58.727; 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-05-10 21:49:58.727; 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-05-10 21:49:58.727; 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-05-10 21:49:58.727; 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-05-10 21:49:58.727; 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-05-10 21:49:59.114; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.114; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:56814 collection:collection1 shard:shard1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.118; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:56814/collection1/ and leader is http://127.0.0.1:39507/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.118; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56814
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.119; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.119; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.120; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.120; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.120; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.121; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.121; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.122; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.123; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.123; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.123; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.144; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:56814__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.364; org.eclipse.jetty.server.Server; jetty-8.1.10.v20130312
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.368; org.eclipse.jetty.server.AbstractConnector; Started SocketConnector@127.0.0.1:62796
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.369; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init()
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.369; org.apache.solr.core.SolrResourceLoader; JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.370; org.apache.solr.core.SolrResourceLoader; using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.370; org.apache.solr.core.CoreContainer$Initializer; looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/solr.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.371; org.apache.solr.core.CoreContainer; New CoreContainer 119266565
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.372; org.apache.solr.core.CoreContainer; Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.372; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/'
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.501; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting socketTimeout to: 120000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.502; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting urlScheme to: http://
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.503; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting connTimeout to: 15000
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.503; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxConnectionsPerHost to: 20
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.504; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting corePoolSize to: 0
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.504; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maximumPoolSize to: 2147483647
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.505; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting maxThreadIdleTime to: 5
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.506; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting sizeOfQueue to: -1
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.506; org.apache.solr.handler.component.HttpShardHandlerFactory; Setting fairnessPolicy to: false
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.507; 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-05-10 21:49:59.523; org.apache.solr.logging.LogWatcher; Registering Log Listener
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.524; org.apache.solr.core.ZkContainer; Zookeeper client=127.0.0.1:49972/solr
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.525; org.apache.solr.cloud.ZkController; zkHost includes chroot
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.526; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.528; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@56a24c85 name:ZooKeeperConnection Watcher:127.0.0.1:49972 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.529; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.532; 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-05-10 21:49:59.545; org.apache.solr.common.cloud.ConnectionManager; Waiting for client to connect to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.547; org.apache.solr.common.cloud.ConnectionManager; Watcher org.apache.solr.common.cloud.ConnectionManager@28d8a549 name:ZooKeeperConnection Watcher:127.0.0.1:49972/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.548; org.apache.solr.common.cloud.ConnectionManager; Client is connected to ZooKeeper
[junit4:junit4] 1> INFO - 2013-05-10 21:49:59.559; org.apache.solr.common.cloud.ZkStateReader; Updating cluster state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.232; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.234; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:56814__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:56814_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56814"}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.248; 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-05-10 21:50:00.248; 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-05-10 21:50:00.248; 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-05-10 21:50:00.248; 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-05-10 21:50:00.248; 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-05-10 21:50:00.248; 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-05-10 21:50:00.563; org.apache.solr.cloud.ZkController; Register node as live in ZooKeeper:/live_nodes/127.0.0.1:62796_
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.566; org.apache.solr.common.cloud.SolrZkClient; makePath: /live_nodes/127.0.0.1:62796_
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.569; 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-05-10 21:50:00.569; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.569; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.569; 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-05-10 21:50:00.569; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.569; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.569; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.571; 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-05-10 21:50:00.571; org.apache.solr.common.cloud.ZkStateReader$3; Updating live nodes... (5)
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.571; 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-05-10 21:50:00.570; 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-05-10 21:50:00.571; 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-05-10 21:50:00.583; org.apache.solr.core.CoreContainer; Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.583; org.apache.solr.cloud.ZkController; Check for collection zkNode:collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.584; org.apache.solr.cloud.ZkController; Collection zkNode exists
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.584; org.apache.solr.cloud.ZkController; Load collection config from:/collections/collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.586; org.apache.solr.core.SolrResourceLoader; new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/collection1/'
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.588; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/collection1/lib/classes/' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.588; org.apache.solr.core.SolrResourceLoader; Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/collection1/lib/README' to classloader
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.643; org.apache.solr.core.SolrConfig; Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.709; org.apache.solr.core.SolrConfig; Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.811; org.apache.solr.schema.IndexSchema; Reading Solr Schema from schema.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:50:00.817; org.apache.solr.schema.IndexSchema; [collection1] Schema name=test
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.146; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:56814__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.147; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:56814__collection1&state=recovering&nodeName=127.0.0.1:56814_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.468; org.apache.solr.schema.IndexSchema; default search field in schema is text
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.473; org.apache.solr.schema.IndexSchema; unique key field: id
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.476; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.482; org.apache.solr.schema.FileExchangeRateProvider; Reloading exchange rates from file currency.xml
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.513; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.514; org.apache.solr.core.SolrCore; [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368222599142/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.514; org.apache.solr.core.JmxMonitoredMap; JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.515; org.apache.solr.core.SolrCore; org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.516; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.516; org.apache.solr.core.SolrCore; New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index/
[junit4:junit4] 1> WARN - 2013-05-10 21:50:01.516; org.apache.solr.core.SolrCore; [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.517; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.521; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.521; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.525; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.525; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.526; org.apache.solr.update.processor.UpdateRequestProcessorChain; inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.527; org.apache.solr.core.RequestHandlers; created standard: solr.StandardRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.527; org.apache.solr.core.RequestHandlers; created /get: solr.RealTimeGetHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.528; org.apache.solr.core.RequestHandlers; adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.528; org.apache.solr.core.RequestHandlers; created /replication: solr.ReplicationHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.529; org.apache.solr.core.RequestHandlers; created /update: solr.UpdateRequestHandler
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.530; org.apache.solr.core.RequestHandlers; created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.544; org.apache.solr.handler.loader.XMLLoader; xsltCacheLifetimeSeconds=60
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.551; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@76f71b70 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.552; org.apache.solr.update.UpdateHandler; Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/tlog
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.553; org.apache.solr.update.CommitTracker; Hard AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.554; org.apache.solr.update.CommitTracker; Soft AutoCommit: disabled
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.558; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@76f71b70 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.561; org.apache.solr.cloud.ZkController; publishing core=collection1 state=down
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.561; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.754; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.755; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":null,
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":null,
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:62796_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:62796"}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.755; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Collection already exists with numShards=2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.755; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Assigning new node to shard=shard2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:01.768; 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-05-10 21:50:01.768; 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-05-10 21:50:01.768; 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-05-10 21:50:01.768; 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-05-10 21:50:01.768; 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-05-10 21:50:01.768; 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-05-10 21:50:02.564; org.apache.solr.core.CoreContainer; registering core: collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.564; org.apache.solr.cloud.ZkController; Register replica - core:collection1 address:http://127.0.0.1:62796 collection:collection1 shard:shard2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.568; org.apache.solr.cloud.ZkController; We are http://127.0.0.1:62796/collection1/ and leader is http://127.0.0.1:24039/collection1/
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.569; org.apache.solr.cloud.ZkController; No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:62796
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.569; org.apache.solr.cloud.ZkController; Core needs to recover:collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.569; org.apache.solr.update.DefaultSolrCoreState; Running recovery - first canceling any ongoing recovery
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.570; org.apache.solr.cloud.RecoveryStrategy; Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.570; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.570; org.apache.solr.cloud.RecoveryStrategy; ###### startupVersions=[]
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.571; org.apache.solr.cloud.ZkController; publishing core=collection1 state=recovering
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.571; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.572; org.apache.solr.servlet.SolrDispatchFilter; user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build/solr-core/test/J1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.572; org.apache.solr.servlet.SolrDispatchFilter; SolrDispatchFilter.init() done
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.573; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.582; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.589; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.591; org.apache.solr.cloud.AbstractFullDistribZkTestBase; Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.591; org.apache.solr.cloud.AbstractDistribZkTestBase; Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.592; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:02.595; org.apache.solr.handler.admin.CoreAdminHandler; Going to wait for coreNodeName: 127.0.0.1:62796__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.148; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:39507/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.148; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:56814 START replicas=[http://127.0.0.1:39507/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-10 21:50:03.149; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.150; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.150; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.151; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.151; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.151; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:39507/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.152; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.159; 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-05-10 21:50:03.164; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.167; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59376fee lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bd626c),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.168; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.168; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59376fee lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bd626c),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59376fee lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bd626c),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.169; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.170; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@69f72005 realtime
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.170; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.171; 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 7
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.172; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.172; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.175; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.176; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.176; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.177; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.177; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.179; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.180; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.181; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index.20130510235003180
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.181; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7548a819 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e051385) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.184; 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-05-10 21:50:03.185; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.186; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.187; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.189; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@535852c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47475be3),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@535852c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47475be3),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.189; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.190; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.190; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2953b2e0 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.191; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@2953b2e0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.192; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index.20130510235003180 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index.20130510235003180;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.193; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index.20130510235003180
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.193; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty3/index.20130510235003180
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.193; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.193; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.194; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.194; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.196; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.274; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.275; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:62796__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"recovering",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:62796_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:62796"}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.279; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:56814__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:56814_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56814"}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.294; 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-05-10 21:50:03.295; 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-05-10 21:50:03.295; 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-05-10 21:50:03.295; 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-05-10 21:50:03.295; 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-05-10 21:50:03.295; 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-05-10 21:50:03.594; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.596; org.apache.solr.handler.admin.CoreAdminHandler; Waited coreNodeName: 127.0.0.1:62796__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:03.596; org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:62796__collection1&state=recovering&nodeName=127.0.0.1:62796_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 1> INFO - 2013-05-10 21:50:04.597; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.598; org.apache.solr.cloud.RecoveryStrategy; Attempting to PeerSync from http://127.0.0.1:24039/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.598; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:62796 START replicas=[http://127.0.0.1:24039/collection1/] nUpdates=100
[junit4:junit4] 1> WARN - 2013-05-10 21:50:05.599; org.apache.solr.update.PeerSync; no frame of reference to tell of we've missed updates
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.599; org.apache.solr.cloud.RecoveryStrategy; PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.600; org.apache.solr.cloud.RecoveryStrategy; Starting Replication Recovery. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.600; org.apache.solr.cloud.RecoveryStrategy; Begin buffering updates. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.599; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.600; org.apache.solr.update.UpdateLog; Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.601; org.apache.solr.cloud.RecoveryStrategy; Attempting to replicate from http://127.0.0.1:24039/collection1/. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.602; org.apache.solr.client.solrj.impl.HttpClientUtil; Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.607; 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-05-10 21:50:05.612; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.616; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@483314d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d45b8d),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.616; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.617; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@483314d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d45b8d),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@483314d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d45b8d),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.618; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.618; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@53c2f756 realtime
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.619; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.619; 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 7
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.620; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.620; org.apache.solr.handler.SnapPuller; No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.622; org.apache.solr.handler.ReplicationHandler; Commits will be reserved for 10000
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.623; 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-05-10 21:50:05.623; org.apache.solr.handler.SnapPuller; Master's generation: 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.623; org.apache.solr.handler.SnapPuller; Slave's generation: 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.624; org.apache.solr.handler.SnapPuller; Starting replication process
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.626; org.apache.solr.core.SolrCore; [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.627; org.apache.solr.handler.SnapPuller; Number of files in latest index in master: 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.629; org.apache.solr.core.CachingDirectoryFactory; return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index.20130510235005627
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.629; org.apache.solr.handler.SnapPuller; Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2e512b3f lockFactory=org.apache.lucene.store.NativeFSLockFactory@78e4536d) fullCopy=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.632; 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-05-10 21:50:05.633; org.apache.solr.handler.SnapPuller; Total time taken for download : 0 secs
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.634; org.apache.solr.update.DefaultSolrCoreState; Creating new IndexWriter...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.635; org.apache.solr.update.DefaultSolrCoreState; Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.636; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.637; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.637; org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be used.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.638; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@7719d827 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.639; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@7719d827 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.640; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index.20130510235005627 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index.20130510235005627;done=true>>]
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.640; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index.20130510235005627
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.640; org.apache.solr.core.CachingDirectoryFactory; Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index.20130510235005627
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.641; org.apache.solr.cloud.RecoveryStrategy; No replay needed. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.641; org.apache.solr.cloud.RecoveryStrategy; Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.641; org.apache.solr.cloud.ZkController; publishing core=collection1 state=active
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.641; org.apache.solr.cloud.ZkController; numShards not found on descriptor - reading it from system property
[junit4:junit4] 1> INFO - 2013-05-10 21:50:05.643; org.apache.solr.cloud.RecoveryStrategy; Finished recovery process. core=collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.304; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.305; org.apache.solr.cloud.Overseer$ClusterStateUpdater; Update state numShards=2 message={
[junit4:junit4] 1> "operation":"state",
[junit4:junit4] 1> "core_node_name":"127.0.0.1:62796__collection1",
[junit4:junit4] 1> "numShards":"2",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "roles":null,
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard_state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard_range":null,
[junit4:junit4] 1> "node_name":"127.0.0.1:62796_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:62796"}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.347; 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-05-10 21:50:06.347; 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-05-10 21:50:06.347; 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-05-10 21:50:06.347; 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-05-10 21:50:06.347; 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-05-10 21:50:06.347; 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-05-10 21:50:06.603; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.604; org.apache.solr.cloud.AbstractDistribZkTestBase; Recoveries finished - collection: collection1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.614; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.617; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3724125a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e83416),segFN=segments_1,generation=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.618; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.619; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3724125a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e83416),segFN=segments_1,generation=1}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3724125a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e83416),segFN=segments_2,generation=2}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.619; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.620; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@18fed594 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.621; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.622; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@18fed594 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.622; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.633; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.634; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@483314d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d45b8d),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@483314d6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60d45b8d),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.635; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.635; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@18b60e35 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.636; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.637; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@18b60e35 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.637; org.apache.solr.update.SolrCmdDistributor; Distrib commit to:[StdNode: http://127.0.0.1:39507/collection1/, StdNode: http://127.0.0.1:56814/collection1/, StdNode: http://127.0.0.1:62796/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.640; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.641; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59376fee lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bd626c),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@59376fee lockFactory=org.apache.lucene.store.NativeFSLockFactory@65bd626c),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.642; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.642; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@63eebf0 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.643; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.644; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@63eebf0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.644; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.648; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.648; org.apache.solr.update.DirectUpdateHandler2; start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.649; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.650; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@535852c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47475be3),segFN=segments_2,generation=2}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@535852c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47475be3),segFN=segments_3,generation=3}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.650; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.651; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.652; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@2461e9fd main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.653; org.apache.solr.search.SolrIndexSearcher; Opening Searcher@5f8df810 main
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.654; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.654; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@2461e9fd main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.654; org.apache.solr.update.DirectUpdateHandler2; end_commit_flush
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.655; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.655; org.apache.solr.core.SolrCore; [collection1] Registered new searcher Searcher@5f8df810 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.656; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.657; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.658; org.apache.solr.common.cloud.ZkStateReader; Updating cloud state from ZooKeeper...
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.661; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.663; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.664; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:06.666; org.apache.solr.core.SolrCore; [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.672; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1434685390109802496)} 0 2
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.679; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1434685390113996800&update.from=http://127.0.0.1:24039/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1434685390113996800)} 0 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.683; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1434685390117142528&update.from=http://127.0.0.1:39507/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1434685390117142528)} 0 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.684; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1434685390117142528)} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.685; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1434685390113996800)} 0 10
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.689; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1434685390127628288)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.694; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1434685390131822592)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.695; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1434685390131822592)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.696; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.699; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1434685390139162624)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.708; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1434685390144405504)]} 0 1
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.709; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1434685390144405504)]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.710; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 8
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.712; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1434685390152794112)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.717; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1434685390155939840)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.718; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1434685390155939840)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.721; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1434685390162231296)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.726; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1434685390165377024)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.727; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1434685390165377024)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.730; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1434685390171668480)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.737; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1434685390176911360)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.738; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1434685390176911360)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.739; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.742; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1434685390184251392)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.747; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1434685390187397120)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.748; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1434685390187397120)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.749; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1434685390191591424)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.756; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1434685390196834304)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.757; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1434685390196834304)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.758; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.760; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1434685390203125760)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.765; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1434685390206271488)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.766; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1434685390206271488)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.768; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1434685390211514368)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.773; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1434685390214660096)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.774; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1434685390214660096)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.776; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1434685390219902976)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.781; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1434685390223048704)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.782; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1434685390223048704)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.785; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1434685390229340160)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.792; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1434685390234583040)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.793; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1434685390234583040)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.793; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.796; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1434685390240874496)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.801; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1434685390244020224)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.802; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1434685390244020224)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.804; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1434685390249263104)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.811; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1434685390254505984)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.812; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1434685390254505984)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.812; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.815; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1434685390260797440)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.822; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1434685390266040320)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.823; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1434685390266040320)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.823; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.826; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1434685390272331776)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.831; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1434685390275477504)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.832; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1434685390275477504)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.835; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1434685390281768960)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.842; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1434685390287011840)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.843; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1434685390287011840)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.843; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.846; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1434685390293303296)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.853; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1434685390298546176)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.854; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1434685390298546176)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.854; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.857; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1434685390304837632)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.862; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1434685390307983360)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.863; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1434685390307983360)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.866; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1434685390314274816)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.871; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1434685390317420544)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.872; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1434685390317420544)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.874; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1434685390322663424)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.881; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1434685390327906304)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.882; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1434685390327906304)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.882; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.885; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1434685390334197760)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.890; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1434685390337343488)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.891; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1434685390337343488)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.893; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1434685390342586368)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.898; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1434685390345732096)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.899; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1434685390345732096)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.902; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1434685390352023552)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.909; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1434685390357266432)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.910; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1434685390357266432)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.911; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.913; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1434685390363557888)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.918; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1434685390366703616)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.919; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1434685390366703616)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.922; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1434685390372995072)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.927; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1434685390376140800)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.928; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1434685390376140800)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.931; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1434685390382432256)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.938; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1434685390387675136)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.939; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1434685390387675136)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.940; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.942; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1434685390393966592)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.949; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1434685390399209472)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.950; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1434685390399209472)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.951; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.953; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1434685390405500928)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.960; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1434685390410743808)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.961; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1434685390410743808)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.962; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.964; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1434685390417035264)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.971; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1434685390422278144)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.972; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1434685390422278144)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.973; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.975; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1434685390428569600)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.982; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1434685390433812480)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1434685390433812480)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.983; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.986; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1434685390440103936)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.993; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1434685390445346816)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.994; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1434685390445346816)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.994; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:08.997; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1434685390451638272)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.004; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1434685390456881152)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.005; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1434685390456881152)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.006; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.009; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1434685390464221184)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.014; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1434685390467366912)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.015; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1434685390467366912)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.018; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1434685390473658368)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.025; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1434685390478901248)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.026; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1434685390478901248)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.026; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.029; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1434685390485192704)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.036; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1434685390490435584)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.037; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1434685390490435584)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.038; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 6
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.040; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1434685390496727040)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.047; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1434685390501969920)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.048; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1434685390501969920)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.048; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.051; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1434685390508261376)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.058; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1434685390513504256)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.059; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1434685390513504256)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.059; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.062; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1434685390519795712)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.067; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1434685390522941440)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.068; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1434685390522941440)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.070; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1434685390528184320)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.077; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1434685390533427200)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.078; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1434685390533427200)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.078; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 5
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.081; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1434685390539718656)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.086; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:39507/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1434685390542864384)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.087; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1434685390542864384)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.089; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1434685390548107264)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.094; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:24039/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1434685390551252992)]} 0 0
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.095; org.apache.solr.update.processor.LogUpdateProcessor; [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1434685390551252992)]} 0 3
[junit4:junit4] 1> INFO - 2013-05-10 21:50:09.097; org.apache.solr.update.processor.LogUpdateProcess
[...truncated too long message...]
he.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 1> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 1> WARN - 2013-05-10 21:50:49.022; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:62796 couldn't connect to http://127.0.0.1:24039/collection1/, counting as success
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.023; org.apache.solr.update.PeerSync; PeerSync: core=collection1 url=http://127.0.0.1:62796 DONE. sync succeeded
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.023; org.apache.solr.cloud.SyncStrategy; We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.024; org.apache.solr.cloud.ShardLeaderElectionContext; Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.024; org.apache.solr.core.SolrCore; [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@63353863
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.030; org.apache.solr.update.DirectUpdateHandler2; closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=10,adds=10,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=52,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.031; org.apache.solr.update.SolrCoreState; Closing SolrCoreState
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.031; org.apache.solr.update.DefaultSolrCoreState; SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.032; org.apache.solr.update.DefaultSolrCoreState; closing IndexWriter with IndexWriterCloser
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.035; org.apache.solr.core.SolrDeletionPolicy; SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_4,generation=4}
[junit4:junit4] 1> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac84af7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d0a1bb9),segFN=segments_5,generation=5}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.035; org.apache.solr.core.SolrDeletionPolicy; newest commit generation = 5
[junit4:junit4] 1> ERROR - 2013-05-10 21:50:49.036; org.apache.solr.update.TransactionLog; Error: Forcing close of tlog{file=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/tlog/tlog.0000000000000000002 refcount=1}
[junit4:junit4] 1> ERROR - 2013-05-10 21:50:49.036; org.apache.solr.update.TransactionLog; Error: Forcing close of tlog{file=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/tlog/tlog.0000000000000000001 refcount=1}
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.039; org.apache.solr.core.SolrCore; [collection1] Closing main searcher on request.
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.039; org.apache.solr.core.CachingDirectoryFactory; Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.040; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.040; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4/index
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.040; org.apache.solr.core.CachingDirectoryFactory; looking to close ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4;done=false>>]
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.041; org.apache.solr.core.CachingDirectoryFactory; Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368222582145/jetty4
[junit4:junit4] 1> WARN - 2013-05-10 21:50:49.041; org.apache.solr.common.cloud.ZkStateReader$3; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> INFO - 2013-05-10 21:50:49.041; 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> WARN - 2013-05-10 21:50:49.042; org.apache.solr.common.cloud.ZkStateReader$2; ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> WARN - 2013-05-10 21:50:49.042; org.apache.solr.cloud.LeaderElector$1;
[junit4:junit4] 1> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 1> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 1> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 1> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 1> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 1> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 1> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 1> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=SimpleText), _version_=MockFixedIntBlock(blockSize=1899)}, docValues:{}, sim=DefaultSimilarity, locale=fi, timezone=Europe/Berlin
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=3,free=334358792,total=536870912
[junit4:junit4] 2> NOTE: All tests run in this JVM: [QueryElevationComponentTest, TestDistributedGrouping, TestUtils, ClusterStateUpdateTest, XmlUpdateRequestHandlerTest, MultiTermTest, SignatureUpdateProcessorFactoryTest, NumericFieldsTest, TestRealTimeGet, SpellCheckComponentTest, SolrCoreTest, SuggesterTSTTest, TestSolrDeletionPolicy2, MoreLikeThisHandlerTest, BasicDistributedZk2Test, PreAnalyzedFieldTest, TestSolrXml, TestCharFilters, ShowFileRequestHandlerTest, UpdateRequestProcessorFactoryTest, SuggesterTest, SimpleFacetsTest, LeaderElectionIntegrationTest, CollectionsAPIDistributedZkTest, TestFastOutputStream, DistributedQueryElevationComponentTest, TestSolr4Spatial, TestCoreDiscovery, TestSolrQueryParserResource, DefaultValueUpdateProcessorTest, SolrIndexConfigTest, TestJmxIntegration, OpenExchangeRatesOrgProviderTest, UnloadDistributedZkTest, ScriptEngineTest, BinaryUpdateRequestHandlerTest, TestFieldResource, DOMUtilTest, SliceStateTest, OpenCloseCoreStressTest, TestLMJelinekMercerSimilarityFactory, DirectUpdateHandlerTest, DateMathParserTest, RecoveryZkTest, TestBinaryField, LeaderElectionTest, QueryParsingTest, SolrCmdDistributorTest, TestFoldingMultitermQuery, RegexBoostProcessorTest, TestCSVResponseWriter, SpellingQueryConverterTest, AnalysisAfterCoreReloadTest, TestRandomFaceting, QueryResultKeyTest, TestReversedWildcardFilterFactory, ShardSplitTest]
[junit4:junit4] Completed on J1 in 67.30s, 1 test, 1 error <<< FAILURES!
[...truncated 510 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-java7/lucene/common-build.xml:887: There were test failures: 295 suites, 1228 tests, 1 error, 27 ignored (8 assumptions)
Total time: 52 minutes 31 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure